S"11:22:08 INFO | Running autotest_quickmerge step.\n11:22:08 INFO | quickmerge| 11:22:08: INFO: RunCommand: sudo -- /usr/bin/python2.7 /mnt/host/source/chromite/bin/autotest_quickmerge '--board=lumpy'\n11:22:08 INFO | quickmerge| 11:22:08: INFO: RunCommand: find /build/lumpy/usr/local/build/autotest/ -path /build/lumpy/usr/local/build/autotest/ExternalSource -prune -o -path /build/lumpy/usr/local/build/autotest/logs -prune -o -path /build/lumpy/usr/local/build/autotest/results -prune -o -path /build/lumpy/usr/local/build/autotest/site-packages -prune -o -printf '%T@\\n'\n11:22:22 INFO | quickmerge| 11:22:22: INFO: RunCommand: find /mnt/host/source/src/third_party/autotest/files/ -path /mnt/host/source/src/third_party/autotest/files/ExternalSource -prune -o -path /mnt/host/source/src/third_party/autotest/files/logs -prune -o -path /mnt/host/source/src/third_party/autotest/files/results -prune -o -path /mnt/host/source/src/third_party/autotest/files/site-packages -prune -o -printf '%T@\\n'\n11:22:32 INFO | quickmerge| 11:22:32: INFO: The sysroot appears to be newer than the source tree, doing nothing and exiting now.\n11:22:32 INFO | Re-running test_that script in /build/lumpy/usr/local/build/autotest copy of autotest.\n11:22:33 INFO | Began logging to /tmp/test_that_results_zZZfQa\nAdding labels [u'cros-version:ad_hoc_build', u'board:lumpy'] to host chromeos2-row2-rack4-host11.cros\n13:22:33 INFO | Fetching suite for job named telemetry_Crosperf...\n13:22:43 INFO | Scheduling suite for job named telemetry_Crosperf...\n13:22:43 INFO | ... scheduled 1 job(s).\n13:22:43 INFO | autoserv| DEBUG:root:import statsd failed, no stats will be reported.\n13:22:43 INFO | autoserv| Results placed in /tmp/test_that_results_zZZfQa/results-1-telemetry_Crosperf\n13:22:43 INFO | autoserv| Logged pid 25397 to /tmp/test_that_results_zZZfQa/results-1-telemetry_Crosperf/.autoserv_execute\n13:22:43 INFO | autoserv| I am PID 25397\n13:22:43 INFO | autoserv| Not checking if job_repo_url contains autotest packages on ['chromeos2-row2-rack4-host11.cros']\n13:22:43 INFO | autoserv| Processing control file\n13:22:44 INFO | autoserv| START\ttelemetry_Crosperf\ttelemetry_Crosperf\ttimestamp=1401301364\tlocaltime=May 28 11:22:44\n13:22:44 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_HsB3vQssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/tmp/tmpxFy6lj -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=300 -l root -p 22 chromeos2-row2-rack4-host11.cros'\n13:22:45 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x   -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_YTu9wYssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=180 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22 chromeos2-row2-rack4-host11.cros'\n13:22:45 INFO | autoserv| Installing autotest on chromeos2-row2-rack4-host11.cros\n13:22:45 INFO | autoserv| Using installation dir /tmp/sysinfo/autoserv-MxOMOw\n13:22:46 INFO | autoserv| No job_repo_url for <remote host: chromeos2-row2-rack4-host11.cros>\n13:22:46 INFO | autoserv| Could not install autotest using the packaging system: No repos to install an autotest client from. Trying other methods\n13:22:47 INFO | autoserv| Installation of autotest completed\n13:22:47 INFO | autoserv| Installing updated global_config.ini.\n13:22:48 INFO | autoserv| No job_repo_url for <remote host: chromeos2-row2-rack4-host11.cros>\n13:22:48 INFO | autoserv| Executing /tmp/sysinfo/autoserv-MxOMOw/bin/autotest /tmp/sysinfo/autoserv-MxOMOw/control phase 0\n13:22:48 INFO | autoserv| Entered autotestd_monitor.\n13:22:48 INFO | autoserv| Finished launching tail subprocesses.\n13:22:48 INFO | autoserv| Finished waiting on autotestd to start.\n13:22:48 INFO | autoserv| START\t----\t----\ttimestamp=1401301368\tlocaltime=May 28 11:22:48\n13:22:48 INFO | autoserv| GOOD\t----\tsysinfo.before\ttimestamp=1401301368\tlocaltime=May 28 11:22:48\n13:22:48 INFO | autoserv| END GOOD\t----\t----\ttimestamp=1401301368\tlocaltime=May 28 11:22:48\n13:22:48 INFO | autoserv| Got lock of exit_code_file.\n13:22:48 INFO | autoserv| Released lock of exit_code_file and closed it.\n13:22:50 INFO | autoserv| Killing child processes.\n13:22:50 INFO | autoserv| Client complete\n13:22:52 INFO | autoserv| No job_repo_url for <remote host: chromeos2-row2-rack4-host11.cros>\n13:22:52 INFO | autoserv| Executing /tmp/sysinfo/autoserv-MxOMOw/bin/autotest /tmp/sysinfo/autoserv-MxOMOw/control phase 0\n13:22:53 INFO | autoserv| Entered autotestd_monitor.\n13:22:53 INFO | autoserv| Finished launching tail subprocesses.\n13:22:53 INFO | autoserv| Finished waiting on autotestd to start.\n13:22:53 INFO | autoserv| START\t----\t----\ttimestamp=1401301373\tlocaltime=May 28 11:22:53\n13:22:53 INFO | autoserv| GOOD\t----\tsysinfo.iteration.before\ttimestamp=1401301373\tlocaltime=May 28 11:22:53\n13:22:53 INFO | autoserv| END GOOD\t----\t----\ttimestamp=1401301373\tlocaltime=May 28 11:22:53\n13:22:53 INFO | autoserv| Got lock of exit_code_file.\n13:22:53 INFO | autoserv| Released lock of exit_code_file and closed it.\n13:22:55 INFO | autoserv| Killing child processes.\n13:22:55 INFO | autoserv| Client complete\n13:22:55 INFO | autoserv| Using Chrome source tree at /tmp/chrome_root\n13:22:55 INFO | autoserv| CMD: /tmp/chrome_root/src/tools/perf/run_benchmark --browser=cros-chrome --remote=chromeos2-row2-rack4-host11.cros  sunspider\n13:23:35 INFO | autoserv| Telemetry completed with exit code: 0.\n13:23:35 INFO | autoserv| stdout:Pages: [http___www.webkit.org_perf_sunspider-1.0.2_sunspider-1.0.2_driver.html]\n13:23:35 INFO | autoserv| RESULT 3d-cube: 3d-cube= [28,28,28,28,31,26,28,28,28,27] ms\n13:23:35 INFO | autoserv| Avg 3d-cube: 28.000000ms\n13:23:35 INFO | autoserv| Sd  3d-cube: 1.247219ms\n13:23:35 INFO | autoserv| RESULT 3d-morph: 3d-morph= [23,22,22,22,22,22,22,22,22,22] ms\n13:23:35 INFO | autoserv| Avg 3d-morph: 22.100000ms\n13:23:35 INFO | autoserv| Sd  3d-morph: 0.316228ms\n13:23:35 INFO | autoserv| RESULT 3d-raytrace: 3d-raytrace= [26,23,24,25,25,25,26,24,24,25] ms\n13:23:35 INFO | autoserv| Avg 3d-raytrace: 24.700000ms\n13:23:35 INFO | autoserv| Sd  3d-raytrace: 0.948683ms\n13:23:35 INFO | autoserv| *RESULT Total: Total= [443,440,440,447,451,435,441,449,449,445] ms\n13:23:35 INFO | autoserv| Avg Total: 444.000000ms\n13:23:35 INFO | autoserv| Sd  Total: 5.077182ms\n13:23:35 INFO | autoserv| RESULT access-binary-trees: access-binary-trees= [4,3,5,6,5,5,3,5,5,4] ms\n13:23:35 INFO | autoserv| Avg access-binary-trees: 4.500000ms\n13:23:35 INFO | autoserv| Sd  access-binary-trees: 0.971825ms\n13:23:35 INFO | autoserv| RESULT access-fannkuch: access-fannkuch= [19,18,17,18,17,18,18,18,17,18] ms\n13:23:35 INFO | autoserv| Avg access-fannkuch: 17.800000ms\n13:23:35 INFO | autoserv| Sd  access-fannkuch: 0.632456ms\n13:23:35 INFO | autoserv| RESULT access-nbody: access-nbody= [7,9,8,7,12,8,9,10,8,7] ms\n13:23:35 INFO | autoserv| Avg access-nbody: 8.500000ms\n13:23:35 INFO | autoserv| Sd  access-nbody: 1.581139ms\n13:23:35 INFO | autoserv| RESULT access-nsieve: access-nsieve= [9,8,8,8,8,7,8,7,8,8] ms\n13:23:35 INFO | autoserv| Avg access-nsieve: 7.900000ms\n13:23:35 INFO | autoserv| Sd  access-nsieve: 0.567646ms\n13:23:35 INFO | autoserv| RESULT bitops-3bit-bits-in-byte: bitops-3bit-bits-in-byte= [3,3,3,3,3,3,3,4,4,3] ms\n13:23:35 INFO | autoserv| Avg bitops-3bit-bits-in-byte: 3.200000ms\n13:23:35 INFO | autoserv| Sd  bitops-3bit-bits-in-byte: 0.421637ms\n13:23:35 INFO | autoserv| RESULT bitops-bits-in-byte: bitops-bits-in-byte= [9,9,9,9,9,9,9,9,9,10] ms\n13:23:35 INFO | autoserv| Avg bitops-bits-in-byte: 9.100000ms\n13:23:35 INFO | autoserv| Sd  bitops-bits-in-byte: 0.316228ms\n13:23:35 INFO | autoserv| RESULT bitops-bitwise-and: bitops-bitwise-and= [8,8,7,9,8,9,8,8,9,10] ms\n13:23:35 INFO | autoserv| Avg bitops-bitwise-and: 8.400000ms\n13:23:35 INFO | autoserv| Sd  bitops-bitwise-and: 0.843274ms\n13:23:35 INFO | autoserv| RESULT bitops-nsieve-bits: bitops-nsieve-bits= [9,9,9,9,9,9,9,11,11,9] ms\n13:23:35 INFO | autoserv| Avg bitops-nsieve-bits: 9.400000ms\n13:23:35 INFO | autoserv| Sd  bitops-nsieve-bits: 0.843274ms\n13:23:35 INFO | autoserv| RESULT controlflow-recursive: controlflow-recursive= [5,5,5,4,4,4,5,4,4,4] ms\n13:23:35 INFO | autoserv| Avg controlflow-recursive: 4.400000ms\n13:23:35 INFO | autoserv| Sd  controlflow-recursive: 0.516398ms\n13:23:35 INFO | autoserv| RESULT crypto-aes: crypto-aes= [14,16,15,16,15,14,17,14,15,16] ms\n13:23:35 INFO | autoserv| Avg crypto-aes: 15.200000ms\n13:23:35 INFO | autoserv| Sd  crypto-aes: 1.032796ms\n13:23:35 INFO | autoserv| RESULT crypto-md5: crypto-md5= [10,11,11,11,10,10,11,10,10,11] ms\n13:23:35 INFO | autoserv| Avg crypto-md5: 10.500000ms\n13:23:35 INFO | autoserv| Sd  crypto-md5: 0.527046ms\n13:23:35 INFO | autoserv| RESULT crypto-sha1: crypto-sha1= [11,11,12,12,12,12,12,10,13,11] ms\n13:23:35 INFO | autoserv| Avg crypto-sha1: 11.600000ms\n13:23:35 INFO | autoserv| Sd  crypto-sha1: 0.843274ms\n13:23:35 INFO | autoserv| RESULT date-format-tofte: date-format-tofte= [28,25,25,26,26,27,26,28,27,25] ms\n13:23:35 INFO | autoserv| Avg date-format-tofte: 26.300000ms\n13:23:35 INFO | autoserv| Sd  date-format-tofte: 1.159502ms\n13:23:35 INFO | autoserv| RESULT date-format-xparb: date-format-xparb= [21,22,21,21,21,20,20,20,21,22] ms\n13:23:35 INFO | autoserv| Avg date-format-xparb: 20.900000ms\n13:23:35 INFO | autoserv| Sd  date-format-xparb: 0.737865ms\n13:23:35 INFO | autoserv| RESULT math-cordic: math-cordic= [8,8,8,9,9,9,9,9,9,9] ms\n13:23:35 INFO | autoserv| Avg math-cordic: 8.700000ms\n13:23:35 INFO | autoserv| Sd  math-cordic: 0.483046ms\n13:23:35 INFO | autoserv| RESULT math-partial-sums: math-partial-sums= [22,22,22,21,23,20,20,23,25,22] ms\n13:23:35 INFO | autoserv| Avg math-partial-sums: 22.000000ms\n13:23:35 INFO | autoserv| Sd  math-partial-sums: 1.490712ms\n13:23:35 INFO | autoserv| RESULT math-spectral-norm: math-spectral-norm= [6,7,6,7,7,6,7,6,7,7] ms\n13:23:35 INFO | autoserv| Avg math-spectral-norm: 6.600000ms\n13:23:35 INFO | autoserv| Sd  math-spectral-norm: 0.516398ms\n13:23:35 INFO | autoserv| RESULT regexp-dna: regexp-dna= [16,16,17,16,16,16,16,16,17,16] ms\n13:23:35 INFO | autoserv| Avg regexp-dna: 16.200000ms\n13:23:35 INFO | autoserv| Sd  regexp-dna: 0.421637ms\n13:23:35 INFO | autoserv| RESULT string-base64: string-base64= [17,16,16,16,17,16,16,16,14,16] ms\n13:23:35 INFO | autoserv| Avg string-base64: 16.000000ms\n13:23:35 INFO | autoserv| Sd  string-base64: 0.816497ms\n13:23:35 INFO | autoserv| RESULT string-fasta: string-fasta= [23,22,23,24,23,23,23,25,23,23] ms\n13:23:35 INFO | autoserv| Avg string-fasta: 23.200000ms\n13:23:35 INFO | autoserv| Sd  string-fasta: 0.788811ms\n13:23:35 INFO | autoserv| RESULT string-tagcloud: string-tagcloud= [53,52,54,53,53,52,51,54,53,53] ms\n13:23:35 INFO | autoserv| Avg string-tagcloud: 52.800000ms\n13:23:35 INFO | autoserv| Sd  string-tagcloud: 0.918937ms\n13:23:35 INFO | autoserv| RESULT string-unpack-code: string-unpack-code= [46,47,46,48,47,46,46,47,47,47] ms\n13:23:35 INFO | autoserv| Avg string-unpack-code: 46.700000ms\n13:23:35 INFO | autoserv| Sd  string-unpack-code: 0.674949ms\n13:23:35 INFO | autoserv| RESULT string-validate-input: string-validate-input= [18,20,19,19,19,19,19,21,19,20] ms\n13:23:35 INFO | autoserv| Avg string-validate-input: 19.300000ms\n13:23:35 INFO | autoserv| Sd  string-validate-input: 0.823273ms\n13:23:35 INFO | autoserv| RESULT telemetry_page_measurement_results: num_failed= 0 count\n13:23:35 INFO | autoserv| RESULT telemetry_page_measurement_results: num_errored= 0 count\n13:23:35 INFO | autoserv| \n13:23:35 INFO | autoserv| View result at file:///tmp/chrome_root/src/tools/perf/results.html\n13:23:35 INFO | autoserv| \n13:23:35 INFO | autoserv| stderr:\n13:23:35 INFO | autoserv| No job_repo_url for <remote host: chromeos2-row2-rack4-host11.cros>\n13:23:35 INFO | autoserv| Executing /tmp/sysinfo/autoserv-MxOMOw/bin/autotest /tmp/sysinfo/autoserv-MxOMOw/control phase 0\n13:23:36 INFO | autoserv| Entered autotestd_monitor.\n13:23:36 INFO | autoserv| Finished launching tail subprocesses.\n13:23:36 INFO | autoserv| Finished waiting on autotestd to start.\n13:23:37 INFO | autoserv| START\t----\t----\ttimestamp=1401301417\tlocaltime=May 28 11:23:37\n13:23:37 INFO | autoserv| GOOD\t----\tsysinfo.iteration.after\ttimestamp=1401301417\tlocaltime=May 28 11:23:37\n13:23:37 INFO | autoserv| END GOOD\t----\t----\ttimestamp=1401301417\tlocaltime=May 28 11:23:37\n13:23:37 INFO | autoserv| Got lock of exit_code_file.\n13:23:37 INFO | autoserv| Released lock of exit_code_file and closed it.\n13:23:39 INFO | autoserv| Killing child processes.\n13:23:39 INFO | autoserv| Client complete\n13:23:39 INFO | autoserv| No job_repo_url for <remote host: chromeos2-row2-rack4-host11.cros>\n13:23:40 INFO | autoserv| Executing /tmp/sysinfo/autoserv-MxOMOw/bin/autotest /tmp/sysinfo/autoserv-MxOMOw/control phase 0\n13:23:40 INFO | autoserv| Entered autotestd_monitor.\n13:23:40 INFO | autoserv| Finished launching tail subprocesses.\n13:23:40 INFO | autoserv| Finished waiting on autotestd to start.\n13:23:40 INFO | autoserv| START\t----\t----\ttimestamp=1401301420\tlocaltime=May 28 11:23:40\n13:23:40 INFO | autoserv| GOOD\t----\tsysinfo.after\ttimestamp=1401301420\tlocaltime=May 28 11:23:40\n13:23:40 INFO | autoserv| END GOOD\t----\t----\ttimestamp=1401301420\tlocaltime=May 28 11:23:40\n13:23:40 INFO | autoserv| Got lock of exit_code_file.\n13:23:40 INFO | autoserv| Released lock of exit_code_file and closed it.\n13:23:42 INFO | autoserv| Killing child processes.\n13:23:42 INFO | autoserv| Client complete\n13:23:44 INFO | autoserv| GOOD\ttelemetry_Crosperf\ttelemetry_Crosperf\ttimestamp=1401301424\tlocaltime=May 28 11:23:44\tcompleted successfully\n13:23:44 INFO | autoserv| END GOOD\ttelemetry_Crosperf\ttelemetry_Crosperf\ttimestamp=1401301424\tlocaltime=May 28 11:23:44\n13:23:44 INFO | autoserv| Finished processing control file\n13:23:44 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_UyjlWMssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/tmp/tmpCvMigR -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=300 -l root -p 22 chromeos2-row2-rack4-host11.cros'\n13:23:45 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x   -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_w_KGTassh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=180 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22 chromeos2-row2-rack4-host11.cros'\n-----------------------------------------------------------------------------------------\n/tmp/test_that_results_zZZfQa/results-1-telemetry_Crosperf                    [  PASSED  ]\n/tmp/test_that_results_zZZfQa/results-1-telemetry_Crosperf/telemetry_Crosperf [  PASSED  ]\n-----------------------------------------------------------------------------------------\nTotal PASS: 2/2 (100%)\n\n13:23:47 INFO | Finished running tests. Results can be found in /tmp/test_that_results_zZZfQa\n"
p0
.S'INFO:root:Identity added: /tmp/test_that_results_PPRMIh/testing_rsa (/tmp/test_that_results_PPRMIh/testing_rsa)\nINFO:root:Identity added: /tmp/test_that_results_zZZfQa/testing_rsa (/tmp/test_that_results_zZZfQa/testing_rsa)\n'
p0
.I0
.