Back to build
Raw log | Switch to full mode | Login

Running command: /b/s/w/ir/cache/vpython/7c7ecd/bin/python scons.py --verbose -k -j1 --mode=nacl,dbg-host platform=x86-64 --clang large_tests force_sel_ldr=../out_64/sel_ldr force_irt=../out_64/irt_x64/irt_core.nexe perf_prefix=gn_ scons: Reading SConscript files ... ====================================================================== SCONS ARGS:['scons.py', '--verbose', '-k', '-j1', '--mode=nacl,dbg-host', 'platform=x86-64', '--clang', 'large_tests', 'force_sel_ldr=../out_64/sel_ldr', 'force_irt=../out_64/irt_x64/irt_core.nexe', 'perf_prefix=gn_'] ====================================================================== ====================================================================== Python Info: ====================================================================== darwin 2.7.14+chromium14 (6cc0aad35b-dirty:6cc0aad35b, Oct 3 2017, 17:23:56) [GCC 4.2.1 Compatible Apple LLVM 8.0.0 (clang-800.0.38)] ====================================================================== ENV: ====================================================================== PATH /b/s/w/ir/cache/vpython/7c7ecd/bin:/b/s/w/ir/cipd_bin_packages:/b/s/w/ir/cipd_bin_packages/bin:/b/s/cipd_cache/bin:/opt/local/bin:/opt/local/sbin:/usr/local/sbin:/usr/local/git/bin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/b/s/w/ir/kitchen-checkout/depot_tools ====================================================================== OS: ====================================================================== kern.ostype: Darwin kern.osrelease: 17.5.0 kern.osrevision: 199506 kern.version: Darwin Kernel Version 17.5.0: Mon Mar 5 22:24:32 PST 2018; root:xnu-4570.51.1~1/RELEASE_X86_64 kern.posix1version: 200112 kern.osversion: 17E199 kern.osproductversion: 10.13.4 ====================================================================== CPU: ====================================================================== hw.machine: x86_64 hw.model: VMware7,1 hw.ncpu: 8 hw.ncpu: 8 hw.activecpu: 8 hw.physicalcpu: 8 hw.physicalcpu_max: 8 hw.logicalcpu: 8 hw.logicalcpu_max: 8 hw.cputype: 7 hw.cpusubtype: 4 hw.cpu64bit_capable: 1 hw.cpufamily: 526772277 hw.cpufrequency: 2574000000 hw.cpufrequency_min: 2574000000 hw.cpufrequency_max: 2574000000 ====================================================================== RAM: ====================================================================== hw.memsize: 17179869184 ====================================================================== LOAD: ====================================================================== TBD ====================================================================== UPTIME: ====================================================================== kern.boottime: { sec = 1547675700, usec = 117403 } Wed Jan 16 13:55:00 2019 ====================================================================== The following environments have been configured ====================================================================== NACL_BUILD_FAMILY: UNTRUSTED BUILD_TYPE: nacl TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/obj BUILD_TYPE_DESCRIPTION: NaCl module build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang ASPPCOM: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_GNU_SOURCE=1 -D_POSIX_C_SOURCE=199506 -D_XOPEN_SOURCE=600 -DDYNAMIC_ANNOTATIONS_ENABLED=1 -DDYNAMIC_ANNOTATIONS_PREFIX=NACL_ -DNACL_BUILD_ARCH=x86 -DNACL_BUILD_SUBARCH=64 -I/b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/include -I/b/s/w/ir/kitchen-workdir -c -o UNKNOWN COMPILER NACL_BUILD_FAMILY: TRUSTED BUILD_TYPE: dbg-mac TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj BUILD_TYPE_DESCRIPTION: MacOS dbg build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/third_party/llvm-build/Release+Asserts/bin/clang ASPPCOM: /b/s/w/ir/kitchen-workdir/third_party/llvm-build/Release+Asserts/bin/clang -isysroot /b/s/w/ir/cache/osx_sdk/XCode.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX10.13.sdk -mmacosx-version-min=10.6 -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_DEBUG -I/b/s/w/ir/kitchen-workdir -c -o UNKNOWN COMPILER NACL_BUILD_FAMILY: UNTRUSTED_IRT BUILD_TYPE: nacl_irt TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64/obj BUILD_TYPE_DESCRIPTION: NaCl IRT build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang ASPPCOM: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_GNU_SOURCE=1 -D_POSIX_C_SOURCE=199506 -D_XOPEN_SOURCE=600 -DDYNAMIC_ANNOTATIONS_ENABLED=1 -DDYNAMIC_ANNOTATIONS_PREFIX=NACL_ -DNACL_BUILD_ARCH=x86 -DNACL_BUILD_SUBARCH=64 -I/b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64/include -I/b/s/w/ir/kitchen-workdir -I/b/s/w/ir/kitchen-workdir/native_client/src/untrusted/pthread -c -o UNKNOWN COMPILER *** BROKEN run_ncval_annotate_test *** BROKEN run_gdb_invalid_memory_test *** BROKEN run_nanosleep_test *** BROKEN run_timefuncs_test *** BROKEN run_raw_timefuncs_test *** BROKEN run_main_thread_pthread_exit_test2 *** BROKEN run_overflowinline_test *** BROKEN run_stack_frame_noopt_frame_test *** BROKEN run_stack_frame_noopt_noframe_test *** BROKEN run_stack_frame_opt_frame_test *** BROKEN run_stack_frame_opt_noframe_test *** BROKEN run_vla_test *** BROKEN run_nacl_sync_cond_test SKIPPING test text_overlaps_rodata SKIPPING test text_overlaps_data There are 13 broken tests. ====================================================================== B U I L D - O U T P U T: ====================================================================== scons: done reading SConscript files. scons: Building targets ... /b/s/w/ir/cache/vpython/7c7ecd/bin/python tools/command_tester.py --name nacl_newlib.run_benchmark_test --time_warning 10 --time_error 100 --perf_env_description gn_x86-64_nnacl_newlib_static --subarch 64 --arch x86 --capture_output 0 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/test_results/benchmark_test.out /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -- scons-out/nacl-x86-64/obj/tests/benchmark/benchmark_test.nexe gn_x86-64_nnacl_newlib_static [ RUN ] nacl_newlib.run_benchmark_test /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -- scons-out/nacl-x86-64/obj/tests/benchmark/benchmark_test.nexe gn_x86-64_nnacl_newlib_static [20738,2742653824:15:28:24.851120] Native Client module will be loaded at base address 0x000047bd00000000 Running suite of 1 benchmarks: Running Benchmark: Life (SIMD version)... RESULT BenchmarkLife: gn_x86-64_nnacl_newlib_static= {0.076420, 0.003100} seconds --------------------------------------------------------------- Done running benchmark suite. [ OK ] nacl_newlib.run_benchmark_test (910 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python tools/command_tester.py --name nacl_newlib.run_clock_cputime_test --time_warning 60 --time_error 600 --perf_env_description gn_x86-64_nnacl_newlib_static --subarch 64 --arch x86 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/test_results/clock_cputime_test.out /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -- scons-out/nacl-x86-64/obj/tests/clock/clock_test.nexe -c [ RUN ] nacl_newlib.run_clock_cputime_test /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -- scons-out/nacl-x86-64/obj/tests/clock/clock_test.nexe -c WARNING: should have taken less than 60.000000 secs [ OK ] nacl_newlib.run_clock_cputime_test (67520 ms) doSizeCheck(["scons-out/nacl-x86-64/obj/tests/hello_world/hello_world_size.out"], ["scons-out/nacl-x86-64/obj/tests/hello_world/hello_world.nexe"]) RESULT hello_world_size.out: gn_x86-64_nnacl_newlib_static= 525.260 KB RESULT hello_world_size.out: ZIPPED_gn_x86-64_nnacl_newlib_static= 187.859 KB /b/s/w/ir/cache/vpython/7c7ecd/bin/python tools/command_tester.py --name nacl_newlib.run_performance_test --time_warning 10 --time_error 100 --perf_env_description gn_x86-64_nnacl_newlib_static --subarch 64 --arch x86 --capture_output 0 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/test_results/performance_test.out /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -e -- scons-out/nacl-x86-64/obj/tests/performance/performance_test.nexe gn_x86-64_nnacl_newlib_static [ RUN ] nacl_newlib.run_performance_test /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -e -- scons-out/nacl-x86-64/obj/tests/performance/performance_test.nexe gn_x86-64_nnacl_newlib_static [20743,2742653824:15:28:39.335470] Native Client module will be loaded at base address 0x000020ca00000000 TestNull: Measuring real time: 0.026 usec (2.636e-08 sec) per iteration: 2.636e-06 sec for 100 iterations 0.003 usec (2.921e-09 sec) per iteration: 2.921e-06 sec for 1000 iterations 0.002 usec (2.323e-09 sec) per iteration: 2.323e-05 sec for 10000 iterations 0.002 usec (2.4587e-09 sec) per iteration: 0.105841 sec for 43047783 iterations 0.002 usec (2.04828e-09 sec) per iteration: 0.088174 sec for 43047783 iterations 0.002 usec (2.13137e-09 sec) per iteration: 0.0917507 sec for 43047783 iterations 0.002 usec (2.01483e-09 sec) per iteration: 0.0867339 sec for 43047783 iterations 0.002 usec (2.01381e-09 sec) per iteration: 0.0866902 sec for 43047783 iterations mean: 0.002133 usec stddev: 0.000168 usec relative stddev: 7.88% RESULT TestNull: gn_x86-64_nnacl_newlib_static= {0.002133, 0.000168} us Measuring clock cycles: first runs (cycles): 222 21 27 30 30 30 30 21 21 21 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 30 222 min: 21 cycles q1: 21 cycles median: 27 cycles q3: 30 cycles max: 222 cycles RESULT TestNull_CycleCount: gn_x86-64_nnacl_newlib_static= {27, 9} count Apparent clock speed: 12656 MHz TestNaClSyscall: Measuring real time: 0.224 usec (2.2416e-07 sec) per iteration: 2.2416e-05 sec for 100 iterations 0.215 usec (2.15121e-07 sec) per iteration: 0.0959672 sec for 446109 iterations 0.217 usec (2.16601e-07 sec) per iteration: 0.0966278 sec for 446109 iterations 0.214 usec (2.14398e-07 sec) per iteration: 0.0956448 sec for 446109 iterations 0.220 usec (2.20377e-07 sec) per iteration: 0.098312 sec for 446109 iterations 0.246 usec (2.45871e-07 sec) per iteration: 0.109685 sec for 446109 iterations mean: 0.222474 usec stddev: 0.011880 usec relative stddev: 5.34% RESULT TestNaClSyscall: gn_x86-64_nnacl_newlib_static= {0.222474, 0.011880} us Measuring clock cycles: first runs (cycles): 1989 864 819 798 786 873 915 825 810 705 ... slowest runs (cycles): ... 855 855 858 864 867 873 873 897 915 1989 min: 621 cycles q1: 747 cycles median: 777 cycles q3: 810 cycles max: 1989 cycles RESULT TestNaClSyscall_CycleCount: gn_x86-64_nnacl_newlib_static= {777, 63} count Apparent clock speed: 3493 MHz TestSetjmpLongjmp: Measuring real time: 0.024 usec (2.35e-08 sec) per iteration: 2.35e-06 sec for 100 iterations 0.015 usec (1.5288e-08 sec) per iteration: 1.5288e-05 sec for 1000 iterations 0.013 usec (1.34421e-08 sec) per iteration: 0.0879259 sec for 6541077 iterations 0.014 usec (1.36906e-08 sec) per iteration: 0.0895511 sec for 6541077 iterations 0.015 usec (1.48566e-08 sec) per iteration: 0.0971783 sec for 6541077 iterations 0.014 usec (1.35733e-08 sec) per iteration: 0.0887842 sec for 6541077 iterations 0.012 usec (1.20944e-08 sec) per iteration: 0.0791106 sec for 6541077 iterations mean: 0.013531 usec stddev: 0.000878 usec relative stddev: 6.49% RESULT TestSetjmpLongjmp: gn_x86-64_nnacl_newlib_static= {0.013531, 0.000878} us Measuring clock cycles: first runs (cycles): 339 57 33 33 36 24 27 24 36 33 ... slowest runs (cycles): ... 36 36 36 36 36 36 36 36 57 339 min: 24 cycles q1: 24 cycles median: 33 cycles q3: 36 cycles max: 339 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_x86-64_nnacl_newlib_static= {33, 12} count Apparent clock speed: 2439 MHz TestClockGetTime: Measuring real time: 0.314 usec (3.1427e-07 sec) per iteration: 3.1427e-05 sec for 100 iterations 0.306 usec (3.06239e-07 sec) per iteration: 0.0974445 sec for 318197 iterations 0.306 usec (3.06037e-07 sec) per iteration: 0.0973799 sec for 318197 iterations 0.307 usec (3.07103e-07 sec) per iteration: 0.0977192 sec for 318197 iterations 0.351 usec (3.50767e-07 sec) per iteration: 0.111613 sec for 318197 iterations 0.418 usec (4.17876e-07 sec) per iteration: 0.132967 sec for 318197 iterations mean: 0.337604 usec stddev: 0.043652 usec relative stddev: 12.93% RESULT TestClockGetTime: gn_x86-64_nnacl_newlib_static= {0.337604, 0.043652} us Measuring clock cycles: first runs (cycles): 3615 1287 1251 1281 1341 1479 1491 1629 1527 1560 ... slowest runs (cycles): ... 1602 1620 1623 1623 1629 1638 1731 1776 1791 3615 min: 1137 cycles q1: 1287 cycles median: 1386 cycles q3: 1518 cycles max: 3615 cycles RESULT TestClockGetTime_CycleCount: gn_x86-64_nnacl_newlib_static= {1386, 231} count Apparent clock speed: 4105 MHz TestTlsVariable: Measuring real time: 0.019 usec (1.893e-08 sec) per iteration: 1.893e-06 sec for 100 iterations 0.010 usec (9.869e-09 sec) per iteration: 9.869e-06 sec for 1000 iterations 0.010 usec (1.04873e-08 sec) per iteration: 0.000104873 sec for 10000 iterations 0.008 usec (7.67932e-09 sec) per iteration: 0.073225 sec for 9535342 iterations 0.007 usec (7.0507e-09 sec) per iteration: 0.0672308 sec for 9535342 iterations 0.007 usec (6.91717e-09 sec) per iteration: 0.0659576 sec for 9535342 iterations 0.006 usec (6.11189e-09 sec) per iteration: 0.0582789 sec for 9535342 iterations 0.007 usec (7.13487e-09 sec) per iteration: 0.0680334 sec for 9535342 iterations mean: 0.006979 usec stddev: 0.000505 usec relative stddev: 7.24% RESULT TestTlsVariable: gn_x86-64_nnacl_newlib_static= {0.006979, 0.000505} us Measuring clock cycles: first runs (cycles): 321 75 21 21 21 33 30 30 30 30 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 33 75 321 min: 21 cycles q1: 21 cycles median: 30 cycles q3: 30 cycles max: 321 cycles RESULT TestTlsVariable_CycleCount: gn_x86-64_nnacl_newlib_static= {30, 9} count Apparent clock speed: 4299 MHz TestMmapAnonymous: Measuring real time: 10.402 usec (1.04022e-05 sec) per iteration: 0.00104022 sec for 100 iterations 11.244 usec (1.12441e-05 sec) per iteration: 0.10809 sec for 9613 iterations 13.150 usec (1.31504e-05 sec) per iteration: 0.126414 sec for 9613 iterations 12.013 usec (1.20127e-05 sec) per iteration: 0.115478 sec for 9613 iterations 10.751 usec (1.07515e-05 sec) per iteration: 0.103354 sec for 9613 iterations 14.279 usec (1.42794e-05 sec) per iteration: 0.137267 sec for 9613 iterations mean: 12.287600 usec stddev: 1.283394 usec relative stddev: 10.44% RESULT TestMmapAnonymous: gn_x86-64_nnacl_newlib_static= {12.287600, 1.283394} us Measuring clock cycles: first runs (cycles): 67503 42336 40878 45819 48468 42705 46464 43668 44871 45096 ... slowest runs (cycles): ... 47154 47397 48249 48468 49566 49887 49926 50889 50985 67503 min: 26064 cycles q1: 26394 cycles median: 26640 cycles q3: 33438 cycles max: 67503 cycles RESULT TestMmapAnonymous_CycleCount: gn_x86-64_nnacl_newlib_static= {26640, 7044} count Apparent clock speed: 2168 MHz TestAtomicIncrement: Measuring real time: 0.020 usec (2.033e-08 sec) per iteration: 2.033e-06 sec for 100 iterations 0.011 usec (1.1278e-08 sec) per iteration: 1.1278e-05 sec for 1000 iterations 0.010 usec (9.98119e-09 sec) per iteration: 0.0885014 sec for 8866820 iterations 0.010 usec (9.70851e-09 sec) per iteration: 0.0860836 sec for 8866820 iterations 0.010 usec (9.70016e-09 sec) per iteration: 0.0860096 sec for 8866820 iterations 0.010 usec (9.70645e-09 sec) per iteration: 0.0860654 sec for 8866820 iterations 0.010 usec (9.70342e-09 sec) per iteration: 0.0860385 sec for 8866820 iterations mean: 0.009760 usec stddev: 0.000111 usec relative stddev: 1.13% RESULT TestAtomicIncrement: gn_x86-64_nnacl_newlib_static= {0.009760, 0.000111} us Measuring clock cycles: first runs (cycles): 258 48 39 51 51 51 51 51 51 51 ... slowest runs (cycles): ... 51 51 51 51 51 51 51 51 51 258 min: 39 cycles q1: 51 cycles median: 51 cycles q3: 51 cycles max: 258 cycles RESULT TestAtomicIncrement_CycleCount: gn_x86-64_nnacl_newlib_static= {51, 0} count Apparent clock speed: 5225 MHz TestUncontendedMutexLock: Measuring real time: 0.029 usec (2.896e-08 sec) per iteration: 2.896e-06 sec for 100 iterations 0.023 usec (2.3416e-08 sec) per iteration: 2.3416e-05 sec for 1000 iterations 0.023 usec (2.32187e-08 sec) per iteration: 0.0991575 sec for 4270584 iterations 0.024 usec (2.37525e-08 sec) per iteration: 0.101437 sec for 4270584 iterations 0.024 usec (2.40707e-08 sec) per iteration: 0.102796 sec for 4270584 iterations 0.025 usec (2.4517e-08 sec) per iteration: 0.104702 sec for 4270584 iterations 0.023 usec (2.31081e-08 sec) per iteration: 0.0986852 sec for 4270584 iterations mean: 0.023733 usec stddev: 0.000526 usec relative stddev: 2.22% RESULT TestUncontendedMutexLock: gn_x86-64_nnacl_newlib_static= {0.023733, 0.000526} us Measuring clock cycles: first runs (cycles): 405 111 87 90 87 90 87 90 78 81 ... slowest runs (cycles): ... 90 90 90 90 90 90 90 90 111 405 min: 78 cycles q1: 81 cycles median: 87 cycles q3: 90 cycles max: 405 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_x86-64_nnacl_newlib_static= {87, 9} count Apparent clock speed: 3666 MHz TestCondvarSignalNoOp: Measuring real time: 0.404 usec (4.0379e-07 sec) per iteration: 4.0379e-05 sec for 100 iterations 0.255 usec (2.54516e-07 sec) per iteration: 0.0630315 sec for 247653 iterations 0.244 usec (2.43897e-07 sec) per iteration: 0.0604019 sec for 247653 iterations 0.258 usec (2.58479e-07 sec) per iteration: 0.064013 sec for 247653 iterations 0.287 usec (2.87255e-07 sec) per iteration: 0.0711397 sec for 247653 iterations 0.246 usec (2.46157e-07 sec) per iteration: 0.0609616 sec for 247653 iterations mean: 0.258061 usec stddev: 0.015539 usec relative stddev: 6.02% RESULT TestCondvarSignalNoOp: gn_x86-64_nnacl_newlib_static= {0.258061, 0.015539} us Measuring clock cycles: first runs (cycles): 3153 915 906 921 894 891 885 864 966 981 ... slowest runs (cycles): ... 1104 1110 1119 1158 1167 1203 1239 1347 1350 3153 min: 825 cycles q1: 900 cycles median: 933 cycles q3: 987 cycles max: 3153 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_x86-64_nnacl_newlib_static= {933, 87} count Apparent clock speed: 3615 MHz TestThreadCreateAndJoin: Measuring real time: 105.941 usec (0.000105941 sec) per iteration: 0.0105941 sec for 100 iterations 96.721 usec (9.67214e-05 sec) per iteration: 0.0912083 sec for 943 iterations 96.422 usec (9.64218e-05 sec) per iteration: 0.0909258 sec for 943 iterations 93.883 usec (9.38825e-05 sec) per iteration: 0.0885312 sec for 943 iterations 105.460 usec (0.00010546 sec) per iteration: 0.0994487 sec for 943 iterations 101.702 usec (0.000101702 sec) per iteration: 0.0959048 sec for 943 iterations mean: 98.837479 usec stddev: 4.169533 usec relative stddev: 4.22% RESULT TestThreadCreateAndJoin: gn_x86-64_nnacl_newlib_static= {98.837479, 4.169533} us Measuring clock cycles: first runs (cycles): 256182 262590 323358 297204 296310 292530 289950 332712 321243 307884 ... slowest runs (cycles): ... 312978 313233 313245 314472 315009 316278 316899 321243 323358 332712 min: 256182 cycles q1: 295314 cycles median: 302451 cycles q3: 306273 cycles max: 332712 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_x86-64_nnacl_newlib_static= {302451, 10959} count Apparent clock speed: 3060 MHz TestThreadWakeup: Measuring real time: 33.140 usec (3.31403e-05 sec) per iteration: 0.00331403 sec for 100 iterations 34.873 usec (3.48728e-05 sec) per iteration: 0.105211 sec for 3017 iterations 35.945 usec (3.59449e-05 sec) per iteration: 0.108446 sec for 3017 iterations 33.543 usec (3.35429e-05 sec) per iteration: 0.101199 sec for 3017 iterations 32.520 usec (3.25202e-05 sec) per iteration: 0.0981135 sec for 3017 iterations 34.908 usec (3.49084e-05 sec) per iteration: 0.105319 sec for 3017 iterations mean: 34.357853 usec stddev: 1.193987 usec relative stddev: 3.48% RESULT TestThreadWakeup: gn_x86-64_nnacl_newlib_static= {34.357853, 1.193987} us Measuring clock cycles: first runs (cycles): 160776 166137 112800 79029 90954 76089 123552 181929 121929 116403 ... slowest runs (cycles): ... 90954 91314 112800 116403 121929 123552 127539 160776 166137 181929 min: 76089 cycles q1: 84645 cycles median: 85041 cycles q3: 85701 cycles max: 181929 cycles RESULT TestThreadWakeup_CycleCount: gn_x86-64_nnacl_newlib_static= {85041, 1056} count Apparent clock speed: 2475 MHz TestCatchingFault: Measuring real time: 35.184 usec (3.51837e-05 sec) per iteration: 0.00351837 sec for 100 iterations 34.269 usec (3.42692e-05 sec) per iteration: 0.097393 sec for 2842 iterations 35.176 usec (3.51756e-05 sec) per iteration: 0.099969 sec for 2842 iterations 34.524 usec (3.45242e-05 sec) per iteration: 0.0981177 sec for 2842 iterations 37.520 usec (3.75202e-05 sec) per iteration: 0.106633 sec for 2842 iterations 35.579 usec (3.55789e-05 sec) per iteration: 0.101115 sec for 2842 iterations mean: 35.413610 usec stddev: 1.150887 usec relative stddev: 3.25% RESULT TestCatchingFault: gn_x86-64_nnacl_newlib_static= {35.413610, 1.150887} us Measuring clock cycles: first runs (cycles): 154692 97964 94348 92876 94040 264014 168438 148748 155926 125656 ... slowest runs (cycles): ... 147092 148220 148748 154692 155926 160900 168438 169244 177432 264014 min: 92296 cycles q1: 101035 cycles median: 127004 cycles q3: 129432 cycles max: 264014 cycles RESULT TestCatchingFault_CycleCount: gn_x86-64_nnacl_newlib_static= {127004, 28397} count Apparent clock speed: 3586 MHz TestThreadCreateAndJoinAfterSettingFaultHandler: Measuring real time: 94.764 usec (9.4764e-05 sec) per iteration: 0.0094764 sec for 100 iterations 100.015 usec (0.000100015 sec) per iteration: 0.105516 sec for 1055 iterations 94.404 usec (9.44041e-05 sec) per iteration: 0.0995963 sec for 1055 iterations 98.964 usec (9.89644e-05 sec) per iteration: 0.104407 sec for 1055 iterations 98.227 usec (9.82266e-05 sec) per iteration: 0.103629 sec for 1055 iterations 100.688 usec (0.000100688 sec) per iteration: 0.106226 sec for 1055 iterations mean: 98.459670 usec stddev: 2.197385 usec relative stddev: 2.23% RESULT TestThreadCreateAndJoinAfterSettingFaultHandler: gn_x86-64_nnacl_newlib_static= {98.459670, 2.197385} us Measuring clock cycles: first runs (cycles): 331806 294507 305580 307269 290940 275166 274587 266757 270462 265206 ... slowest runs (cycles): ... 303516 303831 305580 307269 308013 310374 313140 318168 331806 396528 min: 229185 cycles q1: 248019 cycles median: 284475 cycles q3: 294741 cycles max: 396528 cycles RESULT TestThreadCreateAndJoinAfterSettingFaultHandler_CycleCount: gn_x86-64_nnacl_newlib_static= {284475, 46722} count Apparent clock speed: 2889 MHz [ OK ] nacl_newlib.run_performance_test (6720 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python /b/s/w/ir/kitchen-workdir/native_client/tools/command_tester.py --name nacl_newlib.run_nacl_clock_cputime_test --time_warning 60 --time_error 600 --perf_env_description gn_trusted_mac_x86-64 --subarch 64 --arch x86 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/test_results/nacl_clock_cputime_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/src/shared/platform/nacl_clock_test -c [ RUN ] nacl_newlib.run_nacl_clock_cputime_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/src/shared/platform/nacl_clock_test -c [ OK ] nacl_newlib.run_nacl_clock_cputime_test (9709 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python /b/s/w/ir/kitchen-workdir/native_client/tools/command_tester.py --name nacl_newlib.run_nacl_interval_multi_reg_test --time_warning 60 --time_error 600 --perf_env_description gn_trusted_mac_x86-64 --subarch 64 --arch x86 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/test_results/nacl_interval_multi_reg_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/src/trusted/interval_multiset/nacl_interval_test -k NaClIntervalListMultiset -k NaClIntervalRangeTree -c 1000000 [ RUN ] nacl_newlib.run_nacl_interval_multi_reg_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/src/trusted/interval_multiset/nacl_interval_test -k NaClIntervalListMultiset -k NaClIntervalRangeTree -c 1000000 [ OK ] nacl_newlib.run_nacl_interval_multi_reg_test (1340 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python /b/s/w/ir/kitchen-workdir/native_client/tools/command_tester.py --name nacl_newlib.run_trusted_performance_test --time_warning 2 --time_error 20 --perf_env_description gn_trusted_mac_x86-64 --subarch 64 --arch x86 --capture_output 0 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/test_results/performance_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/tests/performance/performance_test gn_trusted_mac_x86-64 [ RUN ] nacl_newlib.run_trusted_performance_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/tests/performance/performance_test gn_trusted_mac_x86-64 TestNull: Measuring real time: 0.040 usec (4e-08 sec) per iteration: 4e-06 sec for 100 iterations 0.003 usec (3e-09 sec) per iteration: 3e-06 sec for 1000 iterations 0.003 usec (2.7e-09 sec) per iteration: 2.7e-05 sec for 10000 iterations 0.003 usec (2.88514e-09 sec) per iteration: 0.106857 sec for 37037037 iterations 0.003 usec (3.2613e-09 sec) per iteration: 0.120789 sec for 37037037 iterations 0.003 usec (3.34346e-09 sec) per iteration: 0.123832 sec for 37037037 iterations 0.003 usec (2.98204e-09 sec) per iteration: 0.110446 sec for 37037037 iterations 0.003 usec (2.87361e-09 sec) per iteration: 0.10643 sec for 37037037 iterations mean: 0.003069 usec stddev: 0.000196 usec relative stddev: 6.38% RESULT TestNull: gn_trusted_mac_x86-64= {0.003069, 0.000196} us Measuring clock cycles: first runs (cycles): 480 36 33 36 33 21 27 21 21 21 ... slowest runs (cycles): ... 39 39 39 39 39 39 42 42 48 480 min: 18 cycles q1: 21 cycles median: 30 cycles q3: 33 cycles max: 480 cycles RESULT TestNull_CycleCount: gn_trusted_mac_x86-64= {30, 12} count Apparent clock speed: 9775 MHz TestHostSyscall: Measuring real time: 1.640 usec (1.64e-06 sec) per iteration: 0.000164 sec for 100 iterations 0.995 usec (9.949e-07 sec) per iteration: 0.060664 sec for 60975 iterations 0.985 usec (9.85207e-07 sec) per iteration: 0.060073 sec for 60975 iterations 1.024 usec (1.02406e-06 sec) per iteration: 0.062442 sec for 60975 iterations 1.024 usec (1.02442e-06 sec) per iteration: 0.062464 sec for 60975 iterations 1.024 usec (1.02404e-06 sec) per iteration: 0.062441 sec for 60975 iterations mean: 1.010526 usec stddev: 0.016995 usec relative stddev: 1.68% RESULT TestHostSyscall: gn_trusted_mac_x86-64= {1.010526, 0.016995} us Measuring clock cycles: first runs (cycles): 2967 2724 2700 2691 2679 2691 2691 2688 2682 2688 ... slowest runs (cycles): ... 2724 2724 2727 2730 2733 2733 2739 2742 2793 2967 min: 2679 cycles q1: 2691 cycles median: 2691 cycles q3: 2709 cycles max: 2967 cycles RESULT TestHostSyscall_CycleCount: gn_trusted_mac_x86-64= {2691, 18} count Apparent clock speed: 2663 MHz TestSetjmpLongjmp: Measuring real time: 5.090 usec (5.09e-06 sec) per iteration: 0.000509 sec for 100 iterations 4.855 usec (4.85549e-06 sec) per iteration: 0.095391 sec for 19646 iterations 5.323 usec (5.32292e-06 sec) per iteration: 0.104574 sec for 19646 iterations 4.795 usec (4.79492e-06 sec) per iteration: 0.094201 sec for 19646 iterations 4.919 usec (4.91881e-06 sec) per iteration: 0.096635 sec for 19646 iterations 5.076 usec (5.07645e-06 sec) per iteration: 0.099732 sec for 19646 iterations mean: 4.993719 usec stddev: 0.189449 usec relative stddev: 3.79% RESULT TestSetjmpLongjmp: gn_trusted_mac_x86-64= {4.993719, 0.189449} us Measuring clock cycles: first runs (cycles): 13905 12651 12639 12630 12615 12585 12618 12618 12627 12630 ... slowest runs (cycles): ... 12825 12846 12882 12897 13395 13869 13905 14649 14736 15234 min: 12579 cycles q1: 12627 cycles median: 12678 cycles q3: 12696 cycles max: 15234 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_trusted_mac_x86-64= {12678, 69} count Apparent clock speed: 2539 MHz TestClockGetTime: Measuring real time: 0.080 usec (8e-08 sec) per iteration: 8e-06 sec for 100 iterations 0.086 usec (8.6e-08 sec) per iteration: 8.6e-05 sec for 1000 iterations 0.078 usec (7.82549e-08 sec) per iteration: 0.090994 sec for 1162790 iterations 0.085 usec (8.51048e-08 sec) per iteration: 0.098959 sec for 1162790 iterations 0.087 usec (8.67354e-08 sec) per iteration: 0.100855 sec for 1162790 iterations 0.078 usec (7.78378e-08 sec) per iteration: 0.090509 sec for 1162790 iterations 0.078 usec (7.79848e-08 sec) per iteration: 0.09068 sec for 1162790 iterations mean: 0.081184 usec stddev: 0.003904 usec relative stddev: 4.81% RESULT TestClockGetTime: gn_trusted_mac_x86-64= {0.081184, 0.003904} us Measuring clock cycles: first runs (cycles): 1203 228 216 219 216 216 216 216 219 213 ... slowest runs (cycles): ... 216 216 216 219 219 219 219 228 243 1203 min: 213 cycles q1: 216 cycles median: 216 cycles q3: 216 cycles max: 1203 cycles RESULT TestClockGetTime_CycleCount: gn_trusted_mac_x86-64= {216, 0} count Apparent clock speed: 2661 MHz TestMmapAnonymous: Measuring real time: 3.350 usec (3.35e-06 sec) per iteration: 0.000335 sec for 100 iterations 2.981 usec (2.98144e-06 sec) per iteration: 0.088996 sec for 29850 iterations 2.958 usec (2.95789e-06 sec) per iteration: 0.088293 sec for 29850 iterations 2.964 usec (2.96446e-06 sec) per iteration: 0.088489 sec for 29850 iterations 2.904 usec (2.90439e-06 sec) per iteration: 0.086696 sec for 29850 iterations 3.240 usec (3.24e-06 sec) per iteration: 0.096714 sec for 29850 iterations mean: 3.009635 usec stddev: 0.118033 usec relative stddev: 3.92% RESULT TestMmapAnonymous: gn_trusted_mac_x86-64= {3.009635, 0.118033} us Measuring clock cycles: first runs (cycles): 12219 7980 7866 8001 7869 7893 7881 7917 7860 7950 ... slowest runs (cycles): ... 8025 8025 8025 8034 8037 8052 8079 8082 8085 12219 min: 7857 cycles q1: 7881 cycles median: 7899 cycles q3: 7929 cycles max: 12219 cycles RESULT TestMmapAnonymous_CycleCount: gn_trusted_mac_x86-64= {7899, 48} count Apparent clock speed: 2625 MHz TestAtomicIncrement: Measuring real time: 0.010 usec (1e-08 sec) per iteration: 1e-06 sec for 100 iterations 0.010 usec (1e-08 sec) per iteration: 1e-05 sec for 1000 iterations 0.010 usec (9.7173e-09 sec) per iteration: 0.097173 sec for 10000000 iterations 0.010 usec (9.95e-09 sec) per iteration: 0.0995 sec for 10000000 iterations 0.010 usec (1.00394e-08 sec) per iteration: 0.100394 sec for 10000000 iterations 0.012 usec (1.15102e-08 sec) per iteration: 0.115102 sec for 10000000 iterations 0.010 usec (9.87e-09 sec) per iteration: 0.0987 sec for 10000000 iterations mean: 0.010217 usec stddev: 0.000655 usec relative stddev: 6.41% RESULT TestAtomicIncrement: gn_trusted_mac_x86-64= {0.010217, 0.000655} us Measuring clock cycles: first runs (cycles): 474 66 75 60 72 72 63 63 81 60 ... slowest runs (cycles): ... 78 81 81 81 84 90 93 96 120 474 min: 57 cycles q1: 63 cycles median: 66 cycles q3: 72 cycles max: 474 cycles RESULT TestAtomicIncrement_CycleCount: gn_trusted_mac_x86-64= {66, 9} count Apparent clock speed: 6460 MHz TestUncontendedMutexLock: Measuring real time: 0.300 usec (3e-07 sec) per iteration: 3e-05 sec for 100 iterations 0.030 usec (2.9928e-08 sec) per iteration: 0.009976 sec for 333333 iterations 0.030 usec (2.9736e-08 sec) per iteration: 0.009912 sec for 333333 iterations 0.030 usec (2.9721e-08 sec) per iteration: 0.009907 sec for 333333 iterations 0.029 usec (2.9451e-08 sec) per iteration: 0.009817 sec for 333333 iterations 0.031 usec (3.0588e-08 sec) per iteration: 0.010196 sec for 333333 iterations mean: 0.029885 usec stddev: 0.000383 usec relative stddev: 1.28% RESULT TestUncontendedMutexLock: gn_trusted_mac_x86-64= {0.029885, 0.000383} us Measuring clock cycles: first runs (cycles): 501 117 102 90 102 102 93 102 99 93 ... slowest runs (cycles): ... 105 105 105 105 105 105 105 108 117 501 min: 90 cycles q1: 102 cycles median: 102 cycles q3: 102 cycles max: 501 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_trusted_mac_x86-64= {102, 0} count Apparent clock speed: 3413 MHz TestCondvarSignalNoOp: Measuring real time: 0.110 usec (1.1e-07 sec) per iteration: 1.1e-05 sec for 100 iterations 0.016 usec (1.57542e-08 sec) per iteration: 0.014322 sec for 909090 iterations 0.015 usec (1.53714e-08 sec) per iteration: 0.013974 sec for 909090 iterations 0.016 usec (1.56849e-08 sec) per iteration: 0.014259 sec for 909090 iterations 0.021 usec (2.09616e-08 sec) per iteration: 0.019056 sec for 909090 iterations 0.015 usec (1.50678e-08 sec) per iteration: 0.013698 sec for 909090 iterations mean: 0.016568 usec stddev: 0.002210 usec relative stddev: 13.34% RESULT TestCondvarSignalNoOp: gn_trusted_mac_x86-64= {0.016568, 0.002210} us Measuring clock cycles: first runs (cycles): 669 78 69 69 78 78 69 69 69 78 ... slowest runs (cycles): ... 78 78 78 78 78 78 78 78 81 669 min: 66 cycles q1: 69 cycles median: 69 cycles q3: 78 cycles max: 669 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_trusted_mac_x86-64= {69, 9} count Apparent clock speed: 4165 MHz TestThreadCreateAndJoin: Measuring real time: 72.700 usec (7.27e-05 sec) per iteration: 0.00727 sec for 100 iterations 80.407 usec (8.04065e-05 sec) per iteration: 0.110559 sec for 1375 iterations 78.447 usec (7.84473e-05 sec) per iteration: 0.107865 sec for 1375 iterations 80.329 usec (8.03295e-05 sec) per iteration: 0.110453 sec for 1375 iterations 85.758 usec (8.57578e-05 sec) per iteration: 0.117917 sec for 1375 iterations 85.408 usec (8.5408e-05 sec) per iteration: 0.117436 sec for 1375 iterations mean: 82.069818 usec stddev: 2.955097 usec relative stddev: 3.60% RESULT TestThreadCreateAndJoin: gn_trusted_mac_x86-64= {82.069818, 2.955097} us Measuring clock cycles: first runs (cycles): 351651 309312 168180 194430 176862 287145 199206 188847 311847 168447 ... slowest runs (cycles): ... 310734 311847 312723 312954 315003 315858 316038 320055 322344 351651 min: 144246 cycles q1: 200505 cycles median: 261273 cycles q3: 281703 cycles max: 351651 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_trusted_mac_x86-64= {261273, 81198} count Apparent clock speed: 3184 MHz TestThreadWakeup: Measuring real time: 22.120 usec (2.212e-05 sec) per iteration: 0.002212 sec for 100 iterations 19.993 usec (1.99929e-05 sec) per iteration: 0.090368 sec for 4520 iterations 20.202 usec (2.02018e-05 sec) per iteration: 0.091312 sec for 4520 iterations 20.103 usec (2.01029e-05 sec) per iteration: 0.090865 sec for 4520 iterations 20.666 usec (2.06659e-05 sec) per iteration: 0.09341 sec for 4520 iterations 20.811 usec (2.08106e-05 sec) per iteration: 0.094064 sec for 4520 iterations mean: 20.354823 usec stddev: 0.323238 usec relative stddev: 1.59% RESULT TestThreadWakeup: gn_trusted_mac_x86-64= {20.354823, 0.323238} us Measuring clock cycles: first runs (cycles): 68136 59280 61335 53103 53457 53211 53022 53463 53568 53577 ... slowest runs (cycles): ... 76353 76446 76638 76659 77838 78576 82596 82746 145995 170517 min: 48093 cycles q1: 55731 cycles median: 63594 cycles q3: 71193 cycles max: 170517 cycles RESULT TestThreadWakeup_CycleCount: gn_trusted_mac_x86-64= {63594, 15462} count Apparent clock speed: 3124 MHz WARNING: should have taken less than 2.000000 secs [ OK ] nacl_newlib.run_trusted_performance_test (4060 ms) scons: done building targets. ********************************************************************** COMMAND EXECUTION REPORT ********************************************************************** 6 command_tester.py 1 doSizeCheck ********************************************************************** ENVIRONMENT USAGE REPORT ********************************************************************** 3 dbg-mac-x86-64 4 nacl-x86-64 Command return code: 0