Repository: google/mobly

Issue:
Add timing information for instrumentation tests

Discussion:
xpconanfan: 



Review status: 0 of 4 files reviewed at latest revision, all discussions resolved, some commit checks failed.

---

*[mobly/controllers/android_device_lib/adb.py, line 180 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBjvbMANdfbOTNM2-U:-LCBjvbMANdfbOTNM2-V:b7l1db) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L180)):*
> ```Python
>             raise AdbError(cmd=args, stdout=out, stderr=err, ret_code=ret)
> 
>     def _stream_cmd(self, args, shell, level, handler):
> ```

`_execute_and_process_stdout`

---

*[mobly/controllers/android_device_lib/adb.py, line 203 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBfPD94fYurH-HZEyD:-LCBfPD94fYurH-HZEyE:bpp6stj) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L203)):*
> ```Python
>             shell=shell,
>             bufsize=1)
>         out_buffer = []
> ```

not needed

---

*[mobly/controllers/android_device_lib/adb.py, line 209 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBiHuR8rnHRDx-bEdS:-LCBiHuR8rnHRDx-bEdT:b-l6mwxj) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L209)):*
> ```Python
>             if line:
>                 line = line.decode('utf-8')
>                 logging.log(level, line.rstrip())
> ```

remove

---

*[mobly/controllers/android_device_lib/adb.py, line 211 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBiJcUEBtCnoGwoaZG:-LCBiJcUEBtCnoGwoaZH:b3jasbe) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L211)):*
> ```Python
>                 logging.log(level, line.rstrip())
>                 out_buffer.append(line)
>                 if handler:
> ```

handler is required

---

*[mobly/controllers/android_device_lib/adb.py, line 212 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBiOS_24Z1patPnBHE:-LCBiOSa35mms-i-UJpX:b-oend6p) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L212)):*
> ```Python
>                 out_buffer.append(line)
>                 if handler:
>                     handler(line)
> ```

what if the handler throw an error?

---

*[mobly/controllers/android_device_lib/adb.py, line 215 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBjs9dDT6Wm_UZyWS9:-LCBjs9eAmZg3ACbCv61:bpp6stj) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L215)):*
> ```Python
>             else:
>                 (eof_out, eof_err) = proc.communicate()
>                 out_buffer.append(eof_out)
> ```

not needed

---

*[mobly/controllers/android_device_lib/adb.py, line 220 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBj6MG7ZrCpiqLI7Tl:-LCBj6MG7ZrCpiqLI7Tm:b-uchag3) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L220)):*
> ```Python
>         ret = proc.returncode
>         if ret == 0:
>             return out
> ```

return stderr if there is any?

---

*[mobly/controllers/android_device_lib/adb.py, line 222 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBj8bhDhNpC3DuUuHC:-LCBj8bhDhNpC3DuUuHD:bl10liu) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L222)):*
> ```Python
>             return out
>         else:
>             raise AdbError(cmd=args, stdout=out, stderr=err, ret_code=ret)
> ```

stdout doesn't need to be in this error right?

---


*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/392)*
<!-- Sent from Reviewable.io -->

winterfroststrom: Need to add unit tests/test some process failure scenarios.

---

Review status: 0 of 4 files reviewed at latest revision, 8 unresolved discussions.

---

*[mobly/controllers/android_device_lib/adb.py, line 180 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBjvbMANdfbOTNM2-U:-LCG8a7C60ls5L4qKTud:b-896fix) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L180)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

`_execute_and_process_stdout`
</blockquote></details>

Done.

---

*[mobly/controllers/android_device_lib/adb.py, line 203 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBfPD94fYurH-HZEyD:-LCG8bMF--aVh_9tUFq_:b-896fix) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L203)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

not needed
</blockquote></details>

Done.

---

*[mobly/controllers/android_device_lib/adb.py, line 209 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBiHuR8rnHRDx-bEdS:-LCG8dDm9nm_1gm5GdqO:b-896fix) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L209)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

remove
</blockquote></details>

Done.

---

*[mobly/controllers/android_device_lib/adb.py, line 211 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBiJcUEBtCnoGwoaZG:-LCG8eD9Eyqaj__UoZFU:b-896fix) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L211)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

handler is required
</blockquote></details>

Done.

---

*[mobly/controllers/android_device_lib/adb.py, line 212 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBiOS_24Z1patPnBHE:-LCG8jHS41rApna13Htx:b-896fix) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L212)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

what if the handler throw an error?
</blockquote></details>

Done.

---

*[mobly/controllers/android_device_lib/adb.py, line 215 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBjs9dDT6Wm_UZyWS9:-LCG8kKD2Hmn-IbJqBvA:b-896fix) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L215)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

not needed
</blockquote></details>

Done.

---

*[mobly/controllers/android_device_lib/adb.py, line 220 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBj6MG7ZrCpiqLI7Tl:-LCG8lc_61VKdtc3WOBK:b-896fix) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L220)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

return stderr if there is any?
</blockquote></details>

Done.

---

*[mobly/controllers/android_device_lib/adb.py, line 222 at r2](https://reviewable.io/reviews/google/mobly/392#-LCBj8bhDhNpC3DuUuHC:-LCG8nL5-zQtHHr02Nr6:b-896fix) ([raw file](https://github.com/google/mobly/blob/0497c3b77272c047ac5aee2bef53ef4ccca3586c/mobly/controllers/android_device_lib/adb.py#L222)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

stdout doesn't need to be in this error right?
</blockquote></details>

Done.

---


*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/392#-:-LCG8q6B36XlhYrmpxnm:b-g4nxph)*
<!-- Sent from Reviewable.io -->

winterfroststrom: Added unit tests and tested when process dies randomly.

---

Review status: 0 of 4 files reviewed at latest revision, 8 unresolved discussions.

---



*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/392#-:-LCH-RNkCtcFH8B1X0Ot:b-umsxqg)*
<!-- Sent from Reviewable.io -->

xpconanfan: 



Review status: 0 of 4 files reviewed at latest revision, all discussions resolved.

---

*[mobly/controllers/android_device_lib/adb.py, line 206 at r3](https://reviewable.io/reviews/google/mobly/392#-LC_oUj11zZI2SW6BFxY:-LC_oUj11zZI2SW6BFxZ:bfcm7qw) ([raw file](https://github.com/google/mobly/blob/f4f42130704c02f0cb40b35670586bca7d6abd87/mobly/controllers/android_device_lib/adb.py#L206)):*
> ```Python
>             shell=shell,
>             bufsize=1)
>         err = ''
> ```

not needed?

---

*[mobly/controllers/android_device_lib/adb.py, line 221 at r3](https://reviewable.io/reviews/google/mobly/392#-LC_khCQERM8OBURZEIG:-LC_khCQERM8OBURZEIH:b-bj5aq6) ([raw file](https://github.com/google/mobly/blob/f4f42130704c02f0cb40b35670586bca7d6abd87/mobly/controllers/android_device_lib/adb.py#L221)):*
> ```
> [elided]
> ```

What is elided?...

---


*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/392)*
<!-- Sent from Reviewable.io -->

winterfroststrom: 



Review status: 0 of 4 files reviewed at latest revision, 2 unresolved discussions.

---

*[mobly/controllers/android_device_lib/adb.py, line 206 at r3](https://reviewable.io/reviews/google/mobly/392#-LC_oUj11zZI2SW6BFxY:-LCa2y-22qhSnK9V6gwj:b-896fix) ([raw file](https://github.com/google/mobly/blob/f4f42130704c02f0cb40b35670586bca7d6abd87/mobly/controllers/android_device_lib/adb.py#L206)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

not needed?
</blockquote></details>

Done.

---

*[mobly/controllers/android_device_lib/adb.py, line 221 at r3](https://reviewable.io/reviews/google/mobly/392#-LC_khCQERM8OBURZEIG:-LCa2HHCD0FDbh1fefYe:bta5lbs) ([raw file](https://github.com/google/mobly/blob/f4f42130704c02f0cb40b35670586bca7d6abd87/mobly/controllers/android_device_lib/adb.py#L221)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

> ```
> [elided]
> ```

What is elided?...
</blockquote></details>

it's just to indicate that stdout is missing, would you prefer empty string or None instead?

---


*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/392)*
<!-- Sent from Reviewable.io -->

xpconanfan: 



Review status: 0 of 4 files reviewed at latest revision, 2 unresolved discussions.

---

*[mobly/controllers/android_device_lib/adb.py, line 221 at r3](https://reviewable.io/reviews/google/mobly/392#-LC_khCQERM8OBURZEIG:-LCaOWPv9OG92CD17Pzd:bs8gkfc) ([raw file](https://github.com/google/mobly/blob/f4f42130704c02f0cb40b35670586bca7d6abd87/mobly/controllers/android_device_lib/adb.py#L221)):*
<details><summary><i>Previously, winterfroststrom wrote…</i></summary><blockquote>

it's just to indicate that stdout is missing, would you prefer empty string or None instead?
</blockquote></details>

Should we add a more specific msg explaining that stdout has already been piped through the handler?

---

*[mobly/controllers/android_device_lib/adb.py, line 331 at r4](https://reviewable.io/reviews/google/mobly/392#-LCaOs5ZBoq-5AmkNi-D:-LCaOs5ZBoq-5AmkNi-E:bx7a4dg) ([raw file](https://github.com/google/mobly/blob/a39e767452e1ba5220345ebec5f521d945d20eea/mobly/controllers/android_device_lib/adb.py#L331)):*
> ```Python
>             runner: string, the test runner name, which defaults to
>                 DEFAULT_INSTRUMENTATION_RUNNER.
>             handler: func, a function to parse the instrumentation output line
> ```

"optional. When specified, does xxx"

---


*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/392)*
<!-- Sent from Reviewable.io -->

winterfroststrom: 



Review status: 0 of 4 files reviewed at latest revision, 3 unresolved discussions.

---

*[mobly/controllers/android_device_lib/adb.py, line 221 at r3](https://reviewable.io/reviews/google/mobly/392#-LC_khCQERM8OBURZEIG:-LCaUIpY3umLkm0YdjzJ:b-896fix) ([raw file](https://github.com/google/mobly/blob/f4f42130704c02f0cb40b35670586bca7d6abd87/mobly/controllers/android_device_lib/adb.py#L221)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

Should we add a more specific msg explaining that stdout has already been piped through the handler?
</blockquote></details>

Done.

---

*[mobly/controllers/android_device_lib/adb.py, line 331 at r4](https://reviewable.io/reviews/google/mobly/392#-LCaOs5ZBoq-5AmkNi-D:-LCaUKbUA152l5z1U3Ky:b-896fix) ([raw file](https://github.com/google/mobly/blob/a39e767452e1ba5220345ebec5f521d945d20eea/mobly/controllers/android_device_lib/adb.py#L331)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

"optional. When specified, does xxx"
</blockquote></details>

Done.

---


*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/392)*
<!-- Sent from Reviewable.io -->

xpconanfan: 



Review status: 0 of 4 files reviewed at latest revision, all discussions resolved.

---

*[mobly/controllers/android_device_lib/adb.py, line 336 at r5](https://reviewable.io/reviews/google/mobly/392#-LCac0mS4I0glk8XzpA8:-LCabwlT-XOBIGhkg8H0:b-bxk46c) ([raw file](https://github.com/google/mobly/blob/c37138c24f1393dc30dffa9bdbf41db6fd5f7181/mobly/controllers/android_device_lib/adb.py#L336)):*
> ```
>                 generated; otherwise if not specified, the stdout is simply
>                 returned once the instrumentation is finished.
> ```
"otherwise" is sufficient. remove "if not specified".

---


*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/392)*
<!-- Sent from Reviewable.io -->

xpconanfan: 



Review status: 0 of 4 files reviewed at latest revision, 1 unresolved discussion.

---

*[mobly/base_instrumentation_test.py, line 284 at r5](https://reviewable.io/reviews/google/mobly/392#-LCacEVA7shTjMVPehlV:-LCacEVA7shTjMVPehlW:b9c5inx) ([raw file](https://github.com/google/mobly/blob/c37138c24f1393dc30dffa9bdbf41db6fd5f7181/mobly/base_instrumentation_test.py#L284)):*
> ```Python
> 
>     Attributes:
>         begin_time: string or None, optional timestamp for when the test
> ```

"or None" is not needed?

---


*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/392)*
<!-- Sent from Reviewable.io -->

winterfroststrom: 



Review status: 0 of 4 files reviewed at latest revision, 2 unresolved discussions.

---

*[mobly/base_instrumentation_test.py, line 284 at r5](https://reviewable.io/reviews/google/mobly/392#-LCacEVA7shTjMVPehlV:-LCaeAvNAb_3fda-yQG8:b-896fix) ([raw file](https://github.com/google/mobly/blob/c37138c24f1393dc30dffa9bdbf41db6fd5f7181/mobly/base_instrumentation_test.py#L284)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

"or None" is not needed?
</blockquote></details>

Done.

---

*[mobly/controllers/android_device_lib/adb.py, line 336 at r5](https://reviewable.io/reviews/google/mobly/392#-LCac0mS4I0glk8XzpA8:-LCaeBet0-UgDN6bB7v_:b-896fix) ([raw file](https://github.com/google/mobly/blob/c37138c24f1393dc30dffa9bdbf41db6fd5f7181/mobly/controllers/android_device_lib/adb.py#L336)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

> ```
>                 generated; otherwise if not specified, the stdout is simply
>                 returned once the instrumentation is finished.
> ```
"otherwise" is sufficient. remove "if not specified".
</blockquote></details>

Done.

---


*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/392)*
<!-- Sent from Reviewable.io -->

xpconanfan: <img class="emoji" title=":lgtm:" alt=":lgtm:" align="absmiddle" src="https://reviewable.io/lgtm.png" height="20" width="61"/>

---

Reviewed 2 of 4 files at r3, 2 of 2 files at r6.
Review status: all files reviewed at latest revision, all discussions resolved.

---



*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/392#-:-LCaef1KC3KP9xeRQjRJ:bnfp4nl)*
<!-- Sent from Reviewable.io -->


Patch:
diff --git a/mobly/controllers/android_device_lib/adb.py b/mobly/controllers/android_device_lib/adb.py
index 3abcaa9..90dcd0b 100644
--- a/mobly/controllers/android_device_lib/adb.py
+++ b/mobly/controllers/android_device_lib/adb.py
@@ -181,6 +181,47 @@ class AdbProxy(object):
         else:
             raise AdbError(cmd=args, stdout=out, stderr=err, ret_code=ret)
 
+    def _execute_and_process_stdout(self, args, shell, handler):
+        """Executes adb commands and processes the stdout with a handler.
+
+        Args:
+            args: string or list of strings, program arguments.
+                See subprocess.Popen() documentation.
+            shell: bool, True to run this command through the system shell,
+                False to invoke it directly. See subprocess.Popen() docs.
+            handler: func, a function to handle adb stdout line by line.
+
+        Returns:
+            The stderr of the adb command run if exit code is 0.
+
+        Raises:
+            AdbError: The adb command exit code is not 0.
+        """
+        proc = subprocess.Popen(
+            args,
+            stdout=subprocess.PIPE,
+            stderr=subprocess.PIPE,
+            shell=shell,
+            bufsize=1)
+        try:
+            while proc.poll() is None:
+                line = proc.stdout.readline()
+                if line:
+                    handler(line)
+                else:
+                    break
+        finally:
+            (_, err) = proc.communicate()
+        ret = proc.returncode
+        if ret == 0:
+            return err
+        else:
+            raise AdbError(
+                cmd=args,
+                stdout='[elided, processed via handler]',
+                stderr=err,
+                ret_code=ret)
+
     def _construct_adb_cmd(self, raw_name, args, shell):
         """Constructs an adb command with arguments for a subprocess call.
 
@@ -225,6 +266,12 @@ class AdbProxy(object):
             adb_cmd, shell=shell, timeout=timeout, stderr=stderr)
         return out
 
+    def _execute_adb_and_process_stdout(self, name, args, shell, handler):
+        adb_cmd = self._construct_adb_cmd(name, args, shell=shell)
+        out = self._execute_and_process_stdout(
+            adb_cmd, shell=shell, handler=handler)
+        return out
+
     def getprop(self, prop_name):
         """Get a property of the device.
 
@@ -262,7 +309,7 @@ class AdbProxy(object):
             return self._exec_adb_cmd(
                 'forward', args, shell, timeout=None, stderr=None)
 
-    def instrument(self, package, options=None, runner=None):
+    def instrument(self, package, options=None, runner=None, handler=None):
         """Runs an instrumentation command on the device.
 
         This is a convenience wrapper to avoid parameter formatting.
@@ -284,9 +331,14 @@ class AdbProxy(object):
                 class.
             runner: string, the test runner name, which defaults to
                 DEFAULT_INSTRUMENTATION_RUNNER.
+            handler: optional func, when specified the function is used to parse
+                the instrumentation stdout line by line as the output is
+                generated; otherwise, the stdout is simply returned once the
+                instrumentation is finished.
 
         Returns:
-            The output of instrumentation command.
+            The stdout of instrumentation command or the stderr if the handler
+                is set.
         """
         if runner is None:
             runner = DEFAULT_INSTRUMENTATION_RUNNER
@@ -302,7 +354,17 @@ class AdbProxy(object):
             options_string, package, runner)
         logging.info('AndroidDevice|%s: Executing adb shell %s', self.serial,
                      instrumentation_command)
-        return self.shell(instrumentation_command)
+        if handler is None:
+            # Flow kept for backwards-compatibility reasons
+            self._exec_adb_cmd(
+                'shell',
+                instrumentation_command,
+                shell=False,
+                timeout=None,
+                stderr=None)
+        else:
+            return self._execute_adb_and_process_stdout(
+                'shell', instrumentation_command, shell=False, handler=handler)
 
     def __getattr__(self, name):
         def adb_call(args=None, shell=False, timeout=None, stderr=None):


Test patch:
diff --git a/mobly/base_instrumentation_test.py b/mobly/base_instrumentation_test.py
index bb72075..32258ca 100644
--- a/mobly/base_instrumentation_test.py
+++ b/mobly/base_instrumentation_test.py
@@ -19,6 +19,7 @@ from enum import Enum
 from mobly import base_test
 from mobly import records
 from mobly import signals
+from mobly import utils
 
 
 class _InstrumentationStructurePrefixes(object):
@@ -280,6 +281,8 @@ class _InstrumentationBlock(object):
     needs to be done for those.
 
     Attributes:
+        begin_time: string, optional timestamp for when the test corresponding
+            to the instrumentation block began.
         current_key: string, the current key that is being parsed, default to
             _InstrumentationKnownStatusKeys.STREAM.
         error_message: string, an error message indicating that something
@@ -302,6 +305,10 @@ class _InstrumentationBlock(object):
         self.state = state
         self.prefix = prefix
         self.previous_instrumentation_block = previous_instrumentation_block
+        if previous_instrumentation_block:
+            # The parser never needs lookback for two previous blocks,
+            # so unset to allow previous blocks to get garbage collected.
+            previous_instrumentation_block.previous_instrumentation_block = None
 
         self._empty = True
         self.error_message = ''
@@ -319,6 +326,8 @@ class _InstrumentationBlock(object):
         }
         self.unknown_keys = defaultdict(list)
 
+        self.begin_time = None
+
     @property
     def is_empty(self):
         """Deteremines whether or not anything has been parsed with this
@@ -371,6 +380,8 @@ class _InstrumentationBlock(object):
             _InstrumentationStructurePrefixes.STATUS_CODE,
             status_code_line,
         )
+        if self.status_code == _InstrumentationStatusCodes.START:
+            self.begin_time = utils.get_current_epoch_time()
 
     def set_key(self, structure_prefix, key_line):
         """Sets the current key for the instrumentation block.
@@ -440,11 +451,14 @@ class _InstrumentationBlock(object):
             self.state = new_state
             return self
         else:
-            return _InstrumentationBlock(
+            next_block = _InstrumentationBlock(
                 state=new_state,
                 prefix=self.prefix,
                 previous_instrumentation_block=self,
             )
+            if self.status_code in _InstrumentationStatusCodeCategories.TIMING:
+                next_block.begin_time = self.begin_time
+            return next_block
 
 
 class _InstrumentationBlockFormatter(object):
@@ -466,6 +480,7 @@ class _InstrumentationBlockFormatter(object):
         for key, value in instrumentation_block.unknown_keys.items():
             self._unknown_keys[key] = '\n'.join(
                 instrumentation_block.unknown_keys[key]).rstrip()
+        self._begin_time = instrumentation_block.begin_time
 
     def _get_name(self):
         """Gets the method name of the test method for the instrumentation
@@ -589,6 +604,9 @@ class _InstrumentationBlockFormatter(object):
             t_name=self._get_full_name(),
             t_class=mobly_test_class,
         )
+        if self._begin_time:
+            tr_record.begin_time = self._begin_time
+
         if self._is_failed():
             tr_record.test_fail(
                 e=signals.TestFailure(details=details, extras=extras))
@@ -923,17 +941,20 @@ class BaseInstrumentationTestClass(base_test.BaseTestClass):
             TestError if the instrumentation run crashed or if parsing the
                 output failed.
         """
-        instrumentation_output = device.adb.instrument(
+        # Dictionary hack to allow overwriting the instrumentation_block in the
+        # parse_instrumentation closure
+        instrumentation_block = [_InstrumentationBlock(prefix=prefix)]
+
+        def parse_instrumentation(raw_line):
+            line = raw_line.rstrip().decode('utf-8')
+            logging.info(line)
+            instrumentation_block[0] = self._parse_line(
+                instrumentation_block[0], line)
+
+        stderr = device.adb.instrument(
             package=package,
             options=options,
             runner=runner,
-        ).decode('utf-8')
-        logging.info('Outputting instrumentation test log...')
-        logging.info(instrumentation_output)
-
-        # TODO(winterfrosts): Implement online output generation and parsing.
-        instrumentation_block = _InstrumentationBlock(prefix=prefix)
-        for line in instrumentation_output.splitlines():
-            instrumentation_block = self._parse_line(instrumentation_block,
-                                                     line)
-        return self._finish_parsing(instrumentation_block)
+            handler=parse_instrumentation)
+
+        return self._finish_parsing(instrumentation_block[0])
diff --git a/tests/mobly/base_instrumentation_test_test.py b/tests/mobly/base_instrumentation_test_test.py
index 3908015..64cd09c 100755
--- a/tests/mobly/base_instrumentation_test_test.py
+++ b/tests/mobly/base_instrumentation_test_test.py
@@ -26,6 +26,8 @@ from mobly.base_instrumentation_test import _InstrumentationStructurePrefixes
 from mobly.base_instrumentation_test import BaseInstrumentationTestClass
 from mobly import config_parser
 from mobly import signals
+from mobly.controllers import android_device
+from mobly.controllers.android_device_lib import adb
 
 # A mock test package for instrumentation.
 MOCK_TEST_PACKAGE = 'com.my.package.test'
@@ -56,10 +58,14 @@ class MockInstrumentationTest(BaseInstrumentationTestClass):
         super(MockInstrumentationTest, self).__init__(mock_test_run_configs)
 
     def run_mock_instrumentation_test(self, instrumentation_output, prefix):
-        mock_device = mock.Mock()
-        mock_device.adb = mock.Mock()
-        mock_device.adb.instrument = mock.MagicMock(
-            return_value=instrumentation_output)
+        def fake_instrument(package, options=None, runner=None, handler=None):
+            for line in instrumentation_output.splitlines():
+                handler(line)
+            return instrumentation_output
+
+        mock_device = mock.Mock(spec=android_device.AndroidDevice)
+        mock_device.adb = mock.Mock(spec=adb.AdbProxy)
+        mock_device.adb.instrument = fake_instrument
         return self.run_instrumentation_test(
             mock_device, MOCK_TEST_PACKAGE, prefix=prefix)
 
@@ -161,7 +167,8 @@ class BaseInstrumentationTestTest(unittest.TestCase):
                                         expected_skipped=[],
                                         expected_completed_and_passed=False,
                                         expected_has_error=False,
-                                        prefix=None):
+                                        prefix=None,
+                                        expected_executed_times=[]):
         result = self.run_instrumentation_test(
             self.convert_to_raw_output(instrumentation_output), prefix=prefix)
         if expected_has_error:
@@ -178,6 +185,12 @@ class BaseInstrumentationTestTest(unittest.TestCase):
         for actual_test, expected_test in zip(result.skipped,
                                               expected_skipped):
             self.assert_equal_test(actual_test, expected_test)
+        if expected_executed_times:
+            for actual_test, expected_time in zip(result.executed,
+                                                  expected_executed_times):
+                (expected_begin_time, expected_end_time) = expected_time
+                self.assertEquals(actual_test.begin_time, expected_begin_time)
+                self.assertEquals(actual_test.end_time, expected_end_time)
 
     def test_run_instrumentation_test_with_invalid_syntax(self):
         instrumentation_output = """\
@@ -256,7 +269,8 @@ INSTRUMENTATION_STATUS_CODE: -1
             logged_format = mock_call[1][0]
             self.assertIsInstance(logged_format, str)
 
-    def test_run_instrumentation_test_with_passing_test(self):
+    @mock.patch('mobly.utils.get_current_epoch_time')
+    def test_run_instrumentation_test_with_passing_test(self, mock_get_time):
         instrumentation_output = """\
 INSTRUMENTATION_STATUS: numtests=1
 INSTRUMENTATION_STATUS: stream=
@@ -285,10 +299,12 @@ INSTRUMENTATION_CODE: -1
         expected_executed = [
             ('com.my.package.test.BasicTest#basicTest', signals.TestPass),
         ]
+        mock_get_time.side_effect = [13, 51]
         self.assert_run_instrumentation_test(
             instrumentation_output,
             expected_executed=expected_executed,
-            expected_completed_and_passed=True)
+            expected_completed_and_passed=True,
+            expected_executed_times=[(13, 51)])
 
     def test_run_instrumentation_test_with_random_whitespace(self):
         instrumentation_output = """\
@@ -690,7 +706,8 @@ INSTRUMENTATION_CODE: -1"""
             expected_skipped=expected_skipped,
             expected_completed_and_passed=True)
 
-    def test_run_instrumentation_test_with_crashed_test(self):
+    @mock.patch('mobly.utils.get_current_epoch_time')
+    def test_run_instrumentation_test_with_crashed_test(self, mock_get_time):
         instrumentation_output = """\
 INSTRUMENTATION_STATUS: class=com.my.package.test.BasicTest
 INSTRUMENTATION_STATUS: current=1
@@ -705,12 +722,15 @@ INSTRUMENTATION_CODE: 0"""
         expected_executed = [
             ('com.my.package.test.BasicTest#crashTest', signals.TestError),
         ]
+        mock_get_time.side_effect = [67, 942]
         self.assert_run_instrumentation_test(
             instrumentation_output,
             expected_executed=expected_executed,
-            expected_has_error=True)
+            expected_has_error=True,
+            expected_executed_times=[(67, 942)])
 
-    def test_run_instrumentation_test_with_crashing_test(self):
+    @mock.patch('mobly.utils.get_current_epoch_time')
+    def test_run_instrumentation_test_with_crashing_test(self, mock_get_time):
         instrumentation_output = """\
 INSTRUMENTATION_STATUS: class=com.my.package.test.BasicTest
 INSTRUMENTATION_STATUS: current=1
@@ -742,10 +762,13 @@ INSTRUMENTATION_CODE: -1"""
             ('com.my.package.test.BasicTest#crashAndRecover2Test',
              signals.TestError),
         ]
+        mock_get_time.side_effect = [16, 412, 4143, 6547]
+        # TODO(winterfrosts): Fix this issue with overlapping timing
         self.assert_run_instrumentation_test(
             instrumentation_output,
             expected_executed=expected_executed,
-            expected_completed_and_passed=True)
+            expected_completed_and_passed=True,
+            expected_executed_times=[(16, 4143), (412, 6547)])
 
     def test_run_instrumentation_test_with_runner_setup_crash(self):
         instrumentation_output = """\
@@ -782,7 +805,8 @@ INSTRUMENTATION_CODE: 0
             expected_executed=expected_executed,
             expected_has_error=True)
 
-    def test_run_instrumentation_test_with_multiple_tests(self):
+    @mock.patch('mobly.utils.get_current_epoch_time')
+    def test_run_instrumentation_test_with_multiple_tests(self, mock_get_time):
         instrumentation_output = """\
 INSTRUMENTATION_STATUS: class=com.my.package.test.BasicTest
 INSTRUMENTATION_STATUS: current=1
@@ -1066,10 +1090,12 @@ INSTRUMENTATION_CODE: -1"""
              signals.TestSkip),
             ('com.my.package.test.BasicTest#ignoredTest', signals.TestSkip),
         ]
+        mock_get_time.side_effect = [54, 64, -1, -1, -1, -1, 89, 94]
         self.assert_run_instrumentation_test(
             instrumentation_output,
             expected_executed=expected_executed,
-            expected_skipped=expected_skipped)
+            expected_skipped=expected_skipped,
+            expected_executed_times=[(54, 64), (89, 94)])
 
     def test__Instrumentation_block_set_key_on_multiple_equals_sign(self):
         value = "blah=blah, blah2=blah2, blah=2=1=2"
diff --git a/tests/mobly/controllers/android_device_lib/adb_test.py b/tests/mobly/controllers/android_device_lib/adb_test.py
index 8004728..1c75a9d 100755
--- a/tests/mobly/controllers/android_device_lib/adb_test.py
+++ b/tests/mobly/controllers/android_device_lib/adb_test.py
@@ -67,6 +67,20 @@ class AdbTest(unittest.TestCase):
         mock_proc.returncode = 0
         return (mock_psutil_process, mock_popen)
 
+    def _mock_execute_and_process_stdout_process(self, mock_popen):
+        # the created proc object in adb._execute_and_process_stdout()
+        mock_proc = mock.Mock()
+        mock_popen.return_value = mock_proc
+
+        mock_popen.return_value.poll.return_value = None
+        mock_popen.return_value.stdout.readline.side_effect = ['']
+
+        mock_proc.communicate = mock.Mock(
+            return_value=(MOCK_DEFAULT_STDOUT.encode('utf-8'),
+                          MOCK_DEFAULT_STDERR.encode('utf-8')))
+        mock_proc.returncode = 0
+        return mock_popen
+
     @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
     @mock.patch('mobly.controllers.android_device_lib.adb.psutil.Process')
     def test_exec_cmd_no_timeout_success(self, mock_psutil_process,
@@ -124,6 +138,73 @@ class AdbTest(unittest.TestCase):
             adb.AdbProxy()._exec_cmd(
                 ['fake_cmd'], shell=False, timeout=-1, stderr=None)
 
+    @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
+    def test_execute_and_process_stdout_reads_stdout(self, mock_popen):
+        self._mock_execute_and_process_stdout_process(mock_popen)
+        mock_popen.return_value.stdout.readline.side_effect = ['1', '2', '']
+        mock_handler = mock.MagicMock()
+
+        err = adb.AdbProxy()._execute_and_process_stdout(
+            ['fake_cmd'], shell=False, handler=mock_handler)
+        self.assertEqual(mock_handler.call_count, 2)
+        mock_handler.assert_any_call('1')
+        mock_handler.assert_any_call('2')
+
+    @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
+    def test_execute_and_process_stdout_when_cmd_exits(self, mock_popen):
+        self._mock_execute_and_process_stdout_process(mock_popen)
+        mock_popen.return_value.poll.side_effect = [None, None, None, 0]
+        mock_popen.return_value.stdout.readline.return_value = '123'
+        mock_handler = mock.MagicMock()
+
+        err = adb.AdbProxy()._execute_and_process_stdout(
+            ['fake_cmd'], shell=False, handler=mock_handler)
+
+    @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
+    def test_execute_and_process_stdout_when_cmd_eof(self, mock_popen):
+        self._mock_execute_and_process_stdout_process(mock_popen)
+        mock_popen.return_value.poll.return_value = None
+        mock_popen.return_value.stdout.readline.side_effect = [
+            '1', '2', '3', ''
+        ]
+        mock_handler = mock.MagicMock()
+
+        err = adb.AdbProxy()._execute_and_process_stdout(
+            ['fake_cmd'], shell=False, handler=mock_handler)
+
+    @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
+    def test_execute_and_process_stdout_returns_stderr(self, mock_popen):
+        self._mock_execute_and_process_stdout_process(mock_popen)
+
+        err = adb.AdbProxy()._execute_and_process_stdout(
+            ['fake_cmd'], shell=False, handler=mock.MagicMock())
+        self.assertEqual(MOCK_DEFAULT_STDERR, err.decode('utf-8'))
+
+    @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
+    def test_execute_and_process_stdout_raises_adb_error(self, mock_popen):
+        self._mock_execute_and_process_stdout_process(mock_popen)
+        mock_popen.return_value.returncode = 1
+
+        with self.assertRaisesRegex(adb.AdbError,
+                                    'Error executing adb cmd .*'):
+            err = adb.AdbProxy()._execute_and_process_stdout(
+                ['fake_cmd'], shell=False, handler=mock.MagicMock())
+
+    @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
+    def test_execute_and_process_stdout_when_handler_crash(self, mock_popen):
+        self._mock_execute_and_process_stdout_process(mock_popen)
+        mock_popen.return_value.stdout.readline.side_effect = [
+            '1', '2', '3', ''
+        ]
+        mock_handler = mock.MagicMock()
+        mock_handler.side_effect = ['', TypeError('fake crash'), '', '']
+
+        with self.assertRaisesRegex(TypeError, 'fake crash'):
+            err = adb.AdbProxy()._execute_and_process_stdout(
+                ['fake_cmd'], shell=False, handler=mock_handler)
+
+        mock_popen.return_value.communicate.assert_called_once_with()
+
     def test_construct_adb_cmd(self):
         adb_cmd = adb.AdbProxy()._construct_adb_cmd(
             'shell', 'arg1', shell=False)
@@ -255,6 +336,24 @@ class AdbTest(unittest.TestCase):
                 mock_exec_cmd.assert_called_once_with(
                     mock_adb_cmd, shell=True, timeout=None, stderr=None)
 
+    def test_execute_adb_and_process_stdout_formats_command(self):
+        with mock.patch.object(adb.AdbProxy, '_execute_and_process_stdout'
+                               ) as mock_execute_and_process_stdout:
+            with mock.patch.object(
+                    adb.AdbProxy,
+                    '_construct_adb_cmd') as mock_construct_adb_cmd:
+                mock_adb_cmd = mock.MagicMock()
+                mock_adb_args = mock.MagicMock()
+                mock_handler = mock.MagicMock()
+                mock_construct_adb_cmd.return_value = mock_adb_cmd
+
+                adb.AdbProxy()._execute_adb_and_process_stdout(
+                    'shell', mock_adb_args, shell=False, handler=mock_handler)
+                mock_construct_adb_cmd.assert_called_once_with(
+                    'shell', mock_adb_args, shell=False)
+                mock_execute_and_process_stdout.assert_called_once_with(
+                    mock_adb_cmd, shell=False, handler=mock_handler)
+
     @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
     @mock.patch('mobly.controllers.android_device_lib.adb.psutil.Process')
     def test_exec_adb_cmd_with_stderr_pipe(self, mock_psutil_process,
@@ -276,7 +375,6 @@ class AdbTest(unittest.TestCase):
         the basic case.
         """
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
-            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             adb.AdbProxy().instrument(MOCK_INSTRUMENTATION_PACKAGE)
             mock_exec_cmd.assert_called_once_with(
                 ['adb', 'shell', MOCK_BASIC_INSTRUMENTATION_COMMAND],
@@ -289,7 +387,6 @@ class AdbTest(unittest.TestCase):
         with a runner specified.
         """
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
-            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             adb.AdbProxy().instrument(
                 MOCK_INSTRUMENTATION_PACKAGE,
                 runner=MOCK_INSTRUMENTATION_RUNNER)
@@ -304,7 +401,6 @@ class AdbTest(unittest.TestCase):
         with options.
         """
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
-            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             adb.AdbProxy().instrument(
                 MOCK_INSTRUMENTATION_PACKAGE,
                 options=MOCK_INSTRUMENTATION_OPTIONS)
@@ -314,6 +410,61 @@ class AdbTest(unittest.TestCase):
                 timeout=None,
                 stderr=None)
 
+    def test_instrument_with_handler(self):
+        """Verifies the AndroidDevice object's instrument command is correct
+        with a handler passed in.
+        """
+
+        def mock_handler(raw_line):
+            pass
+
+        with mock.patch.object(adb.AdbProxy, '_execute_and_process_stdout'
+                               ) as mock_execute_and_process_stdout:
+            adb.AdbProxy().instrument(
+                MOCK_INSTRUMENTATION_PACKAGE, handler=mock_handler)
+            mock_execute_and_process_stdout.assert_called_once_with(
+                ['adb', 'shell', MOCK_BASIC_INSTRUMENTATION_COMMAND],
+                shell=False,
+                handler=mock_handler)
+
+    def test_instrument_with_handler_with_runner(self):
+        """Verifies the AndroidDevice object's instrument command is correct
+        with a handler passed in and a runner specified.
+        """
+
+        def mock_handler(raw_line):
+            pass
+
+        with mock.patch.object(adb.AdbProxy, '_execute_and_process_stdout'
+                               ) as mock_execute_and_process_stdout:
+            adb.AdbProxy().instrument(
+                MOCK_INSTRUMENTATION_PACKAGE,
+                runner=MOCK_INSTRUMENTATION_RUNNER,
+                handler=mock_handler)
+            mock_execute_and_process_stdout.assert_called_once_with(
+                ['adb', 'shell', MOCK_RUNNER_INSTRUMENTATION_COMMAND],
+                shell=False,
+                handler=mock_handler)
+
+    def test_instrument_with_handler_with_options(self):
+        """Verifies the AndroidDevice object's instrument command is correct
+        with a handler passed in and options.
+        """
+
+        def mock_handler(raw_line):
+            pass
+
+        with mock.patch.object(adb.AdbProxy, '_execute_and_process_stdout'
+                               ) as mock_execute_and_process_stdout:
+            adb.AdbProxy().instrument(
+                MOCK_INSTRUMENTATION_PACKAGE,
+                options=MOCK_INSTRUMENTATION_OPTIONS,
+                handler=mock_handler)
+            mock_execute_and_process_stdout.assert_called_once_with(
+                ['adb', 'shell', MOCK_OPTIONS_INSTRUMENTATION_COMMAND],
+                shell=False,
+                handler=mock_handler)
+
     def test_cli_cmd_to_string(self):
         cmd = ['"adb"', 'a b', 'c//']
         self.assertEqual(adb.cli_cmd_to_string(cmd), '\'"adb"\' \'a b\' c//')