[Android] Log instr test start & end.

build/android/pylib/local/device/local_device_instrumentation_test_run.py

 # Copyright 2015 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 import logging
 import os
 import posixpath
 import re
 import time
 
@@ skipping 237 matching lines @@
             device, test_timeout_scale * self._test_instance.timeout_scale)
 
     logging.info('preparing to run %s: %s', test_display_name, test)
 
     if flags:
       self._CreateFlagChangerIfNeeded(device)
       self._flag_changers[str(device)].PushFlags(
         add=flags.add, remove=flags.remove)
 
     try:
+      device.RunShellCommand(
+          ['log', '-p', 'i', '-t',
+           self._test_instance.test_package.split('.')[-1],

[mikecase (-- gone --), 2016/10/01 01:04:38]

is this tag just the word "tests"?

Like "org.chromium.chrome.tests".split('.')[-1]

[jbudorick, 2016/10/04 21:54:25]

Clearly wasn't thinking this through all the way. Changing this, see below.

+           'START %s' % test_name],
+          check_return=True)

[mikecase (-- gone --), 2016/10/01 01:04:38]

So there will be two logs indicating the start of the test.

I tests: START testA                        // Logged here
I TestRunner: started: testA(a.b.c.MyTest)  // Logged by
InstrumentationTestRunner

Should we make it clearer that one of these logs come from host side and just
tag with "test_runner.py"

I test_runner.py: START testA               // Logged here
I TestRunner: started: testA(a.b.c.MyTest)  // Logged by
InstrumentationTestRunner

[jbudorick, 2016/10/04 21:54:25]

Correct.
Switched the tag to test_runner_py.

       time_ms = lambda: int(time.time() * 1e3)
       start_ms = time_ms()
       output = device.StartInstrumentation(
           target, raw=True, extras=extras, timeout=timeout, retries=0)
+    finally:
+      device.RunShellCommand(
+          ['log', '-p', 'i', '-t',
+           self._test_instance.test_package.split('.')[-1],
+           'END %s' % test_name],
+          check_return=True)
       duration_ms = time_ms() - start_ms
-    finally:
       if flags:
         self._flag_changers[str(device)].Restore()
       if test_timeout_scale:
         valgrind_tools.SetChromeTimeoutScale(
             device, self._test_instance.timeout_scale)
 
     # TODO(jbudorick): Make instrumentation tests output a JSON so this
     # doesn't have to parse the output.
     result_code, result_bundle, statuses = (
         self._test_instance.ParseAmInstrumentRawOutput(output))
@@ skipping 97 matching lines @@
         timeout = v
         break
     else:
       logging.warning('Using default 1 minute timeout for %s', test_name)
       timeout = 60
 
     timeout *= cls._GetTimeoutScaleFromAnnotations(annotations)
 
     return timeout