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,opt-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,opt-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 = 1547763288, usec = 570436 } Thu Jan 17 14:14:48 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: opt-mac TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj BUILD_TYPE_DESCRIPTION: MacOS opt 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 -DNDEBUG -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 [51858,2716697472:17:38:09.557825] Native Client module will be loaded at base address 0x000067ba00000000 Running suite of 1 benchmarks: Running Benchmark: Life (SIMD version)... RESULT BenchmarkLife: gn_x86-64_nnacl_newlib_static= {0.066720, 0.003840} seconds --------------------------------------------------------------- Done running benchmark suite. [ OK ] nacl_newlib.run_benchmark_test (860 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 (66009 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 [51865,2716697472:17:38:23.624441] Native Client module will be loaded at base address 0x0000093400000000 TestNull: Measuring real time: 0.007 usec (7.01e-09 sec) per iteration: 7.01e-07 sec for 100 iterations 0.002 usec (2.312e-09 sec) per iteration: 2.312e-06 sec for 1000 iterations 0.002 usec (2.0304e-09 sec) per iteration: 2.0304e-05 sec for 10000 iterations 0.002 usec (1.9231e-09 sec) per iteration: 0.0947152 sec for 49251379 iterations 0.002 usec (1.88272e-09 sec) per iteration: 0.0927266 sec for 49251379 iterations 0.002 usec (1.9071e-09 sec) per iteration: 0.0939275 sec for 49251379 iterations 0.002 usec (1.89474e-09 sec) per iteration: 0.0933184 sec for 49251379 iterations 0.002 usec (1.98804e-09 sec) per iteration: 0.0979137 sec for 49251379 iterations mean: 0.001919 usec stddev: 0.000037 usec relative stddev: 1.93% RESULT TestNull: gn_x86-64_nnacl_newlib_static= {0.001919, 0.000037} us Measuring clock cycles: first runs (cycles): 276 21 21 36 21 33 21 18 21 18 ... slowest runs (cycles): ... 36 36 36 36 36 36 36 36 36 276 min: 18 cycles q1: 18 cycles median: 21 cycles q3: 21 cycles max: 276 cycles RESULT TestNull_CycleCount: gn_x86-64_nnacl_newlib_static= {21, 3} count Apparent clock speed: 10942 MHz TestNaClSyscall: Measuring real time: 0.159 usec (1.59e-07 sec) per iteration: 1.59e-05 sec for 100 iterations 0.158 usec (1.58357e-07 sec) per iteration: 0.0995955 sec for 628930 iterations 0.148 usec (1.4825e-07 sec) per iteration: 0.0932386 sec for 628930 iterations 0.151 usec (1.50695e-07 sec) per iteration: 0.0947766 sec for 628930 iterations 0.161 usec (1.60538e-07 sec) per iteration: 0.100967 sec for 628930 iterations 0.150 usec (1.50341e-07 sec) per iteration: 0.0945541 sec for 628930 iterations mean: 0.153636 usec stddev: 0.004867 usec relative stddev: 3.17% RESULT TestNaClSyscall: gn_x86-64_nnacl_newlib_static= {0.153636, 0.004867} us Measuring clock cycles: first runs (cycles): 684 288 282 282 297 297 297 297 297 297 ... slowest runs (cycles): ... 297 297 297 297 297 297 297 297 297 684 min: 282 cycles q1: 282 cycles median: 297 cycles q3: 297 cycles max: 684 cycles RESULT TestNaClSyscall_CycleCount: gn_x86-64_nnacl_newlib_static= {297, 15} count Apparent clock speed: 1933 MHz TestSetjmpLongjmp: Measuring real time: 0.016 usec (1.583e-08 sec) per iteration: 1.583e-06 sec for 100 iterations 0.012 usec (1.205e-08 sec) per iteration: 1.205e-05 sec for 1000 iterations 0.012 usec (1.19219e-08 sec) per iteration: 0.0989372 sec for 8298755 iterations 0.012 usec (1.16331e-08 sec) per iteration: 0.0965406 sec for 8298755 iterations 0.011 usec (1.14384e-08 sec) per iteration: 0.0949242 sec for 8298755 iterations 0.012 usec (1.15879e-08 sec) per iteration: 0.0961652 sec for 8298755 iterations 0.011 usec (1.13356e-08 sec) per iteration: 0.0940714 sec for 8298755 iterations mean: 0.011583 usec stddev: 0.000200 usec relative stddev: 1.72% RESULT TestSetjmpLongjmp: gn_x86-64_nnacl_newlib_static= {0.011583, 0.000200} us Measuring clock cycles: first runs (cycles): 414 24 33 24 36 24 33 24 33 24 ... slowest runs (cycles): ... 33 33 33 33 33 33 33 33 36 414 min: 21 cycles q1: 24 cycles median: 24 cycles q3: 30 cycles max: 414 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_x86-64_nnacl_newlib_static= {24, 6} count Apparent clock speed: 2072 MHz TestClockGetTime: Measuring real time: 0.162 usec (1.6232e-07 sec) per iteration: 1.6232e-05 sec for 100 iterations 0.161 usec (1.61305e-07 sec) per iteration: 0.0993745 sec for 616067 iterations 0.158 usec (1.57875e-07 sec) per iteration: 0.0972613 sec for 616067 iterations 0.161 usec (1.60893e-07 sec) per iteration: 0.0991211 sec for 616067 iterations 0.167 usec (1.67281e-07 sec) per iteration: 0.103056 sec for 616067 iterations 0.162 usec (1.62212e-07 sec) per iteration: 0.0999335 sec for 616067 iterations mean: 0.161913 usec stddev: 0.003054 usec relative stddev: 1.89% RESULT TestClockGetTime: gn_x86-64_nnacl_newlib_static= {0.161913, 0.003054} us Measuring clock cycles: first runs (cycles): 1641 489 471 474 465 474 471 471 474 471 ... slowest runs (cycles): ... 474 474 474 474 474 477 477 477 489 1641 min: 459 cycles q1: 465 cycles median: 471 cycles q3: 474 cycles max: 1641 cycles RESULT TestClockGetTime_CycleCount: gn_x86-64_nnacl_newlib_static= {471, 9} count Apparent clock speed: 2909 MHz TestTlsVariable: Measuring real time: 0.010 usec (1.018e-08 sec) per iteration: 1.018e-06 sec for 100 iterations 0.006 usec (6.309e-09 sec) per iteration: 6.309e-06 sec for 1000 iterations 0.006 usec (6.0337e-09 sec) per iteration: 6.0337e-05 sec for 10000 iterations 0.006 usec (6.14991e-09 sec) per iteration: 0.101926 sec for 16573578 iterations 0.006 usec (6.1707e-09 sec) per iteration: 0.102271 sec for 16573578 iterations 0.006 usec (6.12822e-09 sec) per iteration: 0.101567 sec for 16573578 iterations 0.006 usec (5.88283e-09 sec) per iteration: 0.0974995 sec for 16573578 iterations 0.006 usec (5.81043e-09 sec) per iteration: 0.0962997 sec for 16573578 iterations mean: 0.006028 usec stddev: 0.000151 usec relative stddev: 2.50% RESULT TestTlsVariable: gn_x86-64_nnacl_newlib_static= {0.006028, 0.000151} us Measuring clock cycles: first runs (cycles): 375 66 24 24 24 24 24 24 24 24 ... slowest runs (cycles): ... 24 24 24 24 24 24 24 24 66 375 min: 21 cycles q1: 24 cycles median: 24 cycles q3: 24 cycles max: 375 cycles RESULT TestTlsVariable_CycleCount: gn_x86-64_nnacl_newlib_static= {24, 0} count Apparent clock speed: 3981 MHz TestMmapAnonymous: Measuring real time: 9.350 usec (9.35047e-06 sec) per iteration: 0.000935047 sec for 100 iterations 9.319 usec (9.31894e-06 sec) per iteration: 0.0996568 sec for 10694 iterations 8.768 usec (8.76755e-06 sec) per iteration: 0.0937602 sec for 10694 iterations 8.603 usec (8.60337e-06 sec) per iteration: 0.0920045 sec for 10694 iterations 8.476 usec (8.4756e-06 sec) per iteration: 0.090638 sec for 10694 iterations 8.608 usec (8.60834e-06 sec) per iteration: 0.0920576 sec for 10694 iterations mean: 8.754761 usec stddev: 0.296902 usec relative stddev: 3.39% RESULT TestMmapAnonymous: gn_x86-64_nnacl_newlib_static= {8.754761, 0.296902} us Measuring clock cycles: first runs (cycles): 34176 25599 24423 24408 24591 24453 24687 24780 24696 24489 ... slowest runs (cycles): ... 24621 24687 24696 24720 24780 24837 25488 25599 34176 36906 min: 24240 cycles q1: 24345 cycles median: 24417 cycles q3: 24510 cycles max: 36906 cycles RESULT TestMmapAnonymous_CycleCount: gn_x86-64_nnacl_newlib_static= {24417, 165} count Apparent clock speed: 2789 MHz TestAtomicIncrement: Measuring real time: 0.015 usec (1.458e-08 sec) per iteration: 1.458e-06 sec for 100 iterations 0.010 usec (9.948e-09 sec) per iteration: 9.948e-06 sec for 1000 iterations 0.010 usec (9.6938e-09 sec) per iteration: 9.6938e-05 sec for 10000 iterations 0.010 usec (1.00096e-08 sec) per iteration: 0.103257 sec for 10315872 iterations 0.009 usec (9.08801e-09 sec) per iteration: 0.0937507 sec for 10315872 iterations 0.009 usec (9.00009e-09 sec) per iteration: 0.0928438 sec for 10315872 iterations 0.009 usec (9.10177e-09 sec) per iteration: 0.0938927 sec for 10315872 iterations 0.010 usec (9.6778e-09 sec) per iteration: 0.099835 sec for 10315872 iterations mean: 0.009375 usec stddev: 0.000398 usec relative stddev: 4.24% RESULT TestAtomicIncrement: gn_x86-64_nnacl_newlib_static= {0.009375, 0.000398} us Measuring clock cycles: first runs (cycles): 267 48 45 45 42 48 48 48 48 45 ... slowest runs (cycles): ... 48 48 48 48 48 48 48 48 48 267 min: 42 cycles q1: 45 cycles median: 48 cycles q3: 48 cycles max: 267 cycles RESULT TestAtomicIncrement_CycleCount: gn_x86-64_nnacl_newlib_static= {48, 3} count Apparent clock speed: 5120 MHz TestUncontendedMutexLock: Measuring real time: 0.028 usec (2.801e-08 sec) per iteration: 2.801e-06 sec for 100 iterations 0.023 usec (2.3295e-08 sec) per iteration: 2.3295e-05 sec for 1000 iterations 0.022 usec (2.19418e-08 sec) per iteration: 0.0941911 sec for 4292766 iterations 0.022 usec (2.23917e-08 sec) per iteration: 0.0961225 sec for 4292766 iterations 0.022 usec (2.24192e-08 sec) per iteration: 0.0962402 sec for 4292766 iterations 0.023 usec (2.26037e-08 sec) per iteration: 0.0970322 sec for 4292766 iterations 0.023 usec (2.31355e-08 sec) per iteration: 0.0993154 sec for 4292766 iterations mean: 0.022498 usec stddev: 0.000386 usec relative stddev: 1.72% RESULT TestUncontendedMutexLock: gn_x86-64_nnacl_newlib_static= {0.022498, 0.000386} us Measuring clock cycles: first runs (cycles): 462 111 81 81 81 81 81 81 81 81 ... slowest runs (cycles): ... 90 90 90 90 90 90 90 90 111 462 min: 81 cycles q1: 81 cycles median: 90 cycles q3: 90 cycles max: 462 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_x86-64_nnacl_newlib_static= {90, 9} count Apparent clock speed: 4000 MHz TestCondvarSignalNoOp: Measuring real time: 0.304 usec (3.0406e-07 sec) per iteration: 3.0406e-05 sec for 100 iterations 0.159 usec (1.58911e-07 sec) per iteration: 0.0522631 sec for 328882 iterations 0.159 usec (1.59406e-07 sec) per iteration: 0.0524258 sec for 328882 iterations 0.159 usec (1.58965e-07 sec) per iteration: 0.0522807 sec for 328882 iterations 0.159 usec (1.58935e-07 sec) per iteration: 0.0522707 sec for 328882 iterations 0.159 usec (1.58829e-07 sec) per iteration: 0.052236 sec for 328882 iterations mean: 0.159009 usec stddev: 0.000204 usec relative stddev: 0.13% RESULT TestCondvarSignalNoOp: gn_x86-64_nnacl_newlib_static= {0.159009, 0.000204} us Measuring clock cycles: first runs (cycles): 1371 438 432 432 432 435 435 435 432 435 ... slowest runs (cycles): ... 435 435 435 438 444 444 444 444 444 1371 min: 432 cycles q1: 432 cycles median: 435 cycles q3: 435 cycles max: 1371 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_x86-64_nnacl_newlib_static= {435, 3} count Apparent clock speed: 2736 MHz TestThreadCreateAndJoin: Measuring real time: 73.905 usec (7.39052e-05 sec) per iteration: 0.00739052 sec for 100 iterations 65.041 usec (6.50408e-05 sec) per iteration: 0.0880002 sec for 1353 iterations 66.818 usec (6.68175e-05 sec) per iteration: 0.0904041 sec for 1353 iterations 65.191 usec (6.51909e-05 sec) per iteration: 0.0882033 sec for 1353 iterations 67.315 usec (6.73152e-05 sec) per iteration: 0.0910775 sec for 1353 iterations 65.006 usec (6.50055e-05 sec) per iteration: 0.0879525 sec for 1353 iterations mean: 65.873996 usec stddev: 0.988170 usec relative stddev: 1.50% RESULT TestThreadCreateAndJoin: gn_x86-64_nnacl_newlib_static= {65.873996, 0.988170} us Measuring clock cycles: first runs (cycles): 172773 183390 204942 194667 184245 222717 225396 176088 178137 173277 ... slowest runs (cycles): ... 194667 199698 200814 204942 206301 206877 212871 222717 225396 260733 min: 165246 cycles q1: 169632 cycles median: 171363 cycles q3: 172773 cycles max: 260733 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_x86-64_nnacl_newlib_static= {171363, 3141} count Apparent clock speed: 2601 MHz TestThreadWakeup: Measuring real time: 31.288 usec (3.1288e-05 sec) per iteration: 0.00312881 sec for 100 iterations 31.158 usec (3.11581e-05 sec) per iteration: 0.0995813 sec for 3196 iterations 31.208 usec (3.12084e-05 sec) per iteration: 0.0997422 sec for 3196 iterations 30.280 usec (3.02797e-05 sec) per iteration: 0.096774 sec for 3196 iterations 31.149 usec (3.11485e-05 sec) per iteration: 0.0995508 sec for 3196 iterations 30.670 usec (3.067e-05 sec) per iteration: 0.0980212 sec for 3196 iterations mean: 30.892956 usec stddev: 0.363572 usec relative stddev: 1.18% RESULT TestThreadWakeup: gn_x86-64_nnacl_newlib_static= {30.892956, 0.363572} us Measuring clock cycles: first runs (cycles): 86574 85620 84432 88608 89430 90378 98541 101409 78900 93879 ... slowest runs (cycles): ... 87198 88608 88611 89430 90378 90822 93879 96144 98541 101409 min: 77373 cycles q1: 83103 cycles median: 84099 cycles q3: 84672 cycles max: 101409 cycles RESULT TestThreadWakeup_CycleCount: gn_x86-64_nnacl_newlib_static= {84099, 1569} count Apparent clock speed: 2722 MHz TestCatchingFault: Measuring real time: 33.399 usec (3.33987e-05 sec) per iteration: 0.00333987 sec for 100 iterations 30.993 usec (3.09931e-05 sec) per iteration: 0.0927934 sec for 2994 iterations 30.925 usec (3.09248e-05 sec) per iteration: 0.0925888 sec for 2994 iterations 30.638 usec (3.0638e-05 sec) per iteration: 0.0917302 sec for 2994 iterations 31.475 usec (3.14755e-05 sec) per iteration: 0.0942376 sec for 2994 iterations 31.803 usec (3.18032e-05 sec) per iteration: 0.0952187 sec for 2994 iterations mean: 31.166912 usec stddev: 0.416804 usec relative stddev: 1.34% RESULT TestCatchingFault: gn_x86-64_nnacl_newlib_static= {31.166912, 0.416804} us Measuring clock cycles: first runs (cycles): 104379 94713 91542 90777 114486 119442 89271 93180 132984 99627 ... slowest runs (cycles): ... 91542 93180 94713 99627 101742 104379 107472 114486 119442 132984 min: 81480 cycles q1: 82314 cycles median: 82797 cycles q3: 83418 cycles max: 132984 cycles RESULT TestCatchingFault_CycleCount: gn_x86-64_nnacl_newlib_static= {82797, 1104} count Apparent clock speed: 2657 MHz TestThreadCreateAndJoinAfterSettingFaultHandler: Measuring real time: 69.144 usec (6.91435e-05 sec) per iteration: 0.00691435 sec for 100 iterations 65.401 usec (6.54006e-05 sec) per iteration: 0.0945693 sec for 1446 iterations 64.552 usec (6.45523e-05 sec) per iteration: 0.0933427 sec for 1446 iterations 63.327 usec (6.33268e-05 sec) per iteration: 0.0915705 sec for 1446 iterations 68.101 usec (6.81012e-05 sec) per iteration: 0.0984744 sec for 1446 iterations 64.537 usec (6.45374e-05 sec) per iteration: 0.0933211 sec for 1446 iterations mean: 65.183671 usec stddev: 1.601465 usec relative stddev: 2.46% RESULT TestThreadCreateAndJoinAfterSettingFaultHandler: gn_x86-64_nnacl_newlib_static= {65.183671, 1.601465} us Measuring clock cycles: first runs (cycles): 178314 187887 167280 179412 201696 250728 180516 181548 176118 176061 ... slowest runs (cycles): ... 180516 181161 181548 183969 187887 188175 200199 201696 203019 250728 min: 167280 cycles q1: 173562 cycles median: 174312 cycles q3: 175923 cycles max: 250728 cycles RESULT TestThreadCreateAndJoinAfterSettingFaultHandler_CycleCount: gn_x86-64_nnacl_newlib_static= {174312, 2361} count Apparent clock speed: 2674 MHz [ OK ] nacl_newlib.run_performance_test (6370 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/opt-mac-x86-64/test_results/nacl_clock_cputime_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-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/opt-mac-x86-64/obj/src/shared/platform/nacl_clock_test -c [ OK ] nacl_newlib.run_nacl_clock_cputime_test (1510 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/opt-mac-x86-64/test_results/nacl_interval_multi_reg_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-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/opt-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 (800 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/opt-mac-x86-64/test_results/performance_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-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/opt-mac-x86-64/obj/tests/performance/performance_test gn_trusted_mac_x86-64 TestNull: Measuring real time: 0.010 usec (1e-08 sec) per iteration: 1e-06 sec for 100 iterations 0.002 usec (2e-09 sec) per iteration: 2e-06 sec for 1000 iterations 0.003 usec (2.5e-09 sec) per iteration: 2.5e-05 sec for 10000 iterations 0.003 usec (2.55275e-09 sec) per iteration: 0.10211 sec for 40000000 iterations 0.003 usec (2.56222e-09 sec) per iteration: 0.102489 sec for 40000000 iterations 0.002 usec (2.48985e-09 sec) per iteration: 0.099594 sec for 40000000 iterations 0.003 usec (2.63897e-09 sec) per iteration: 0.105559 sec for 40000000 iterations 0.003 usec (2.55658e-09 sec) per iteration: 0.102263 sec for 40000000 iterations mean: 0.002560 usec stddev: 0.000047 usec relative stddev: 1.85% RESULT TestNull: gn_trusted_mac_x86-64= {0.002560, 0.000047} us Measuring clock cycles: first runs (cycles): 267 18 21 18 21 18 30 18 21 18 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 30 267 min: 18 cycles q1: 21 cycles median: 21 cycles q3: 21 cycles max: 267 cycles RESULT TestNull_CycleCount: gn_trusted_mac_x86-64= {21, 0} count Apparent clock speed: 8203 MHz TestHostSyscall: Measuring real time: 1.280 usec (1.28e-06 sec) per iteration: 0.000128 sec for 100 iterations 0.982 usec (9.81568e-07 sec) per iteration: 0.076685 sec for 78125 iterations 0.987 usec (9.86854e-07 sec) per iteration: 0.077098 sec for 78125 iterations 0.964 usec (9.6448e-07 sec) per iteration: 0.07535 sec for 78125 iterations 0.952 usec (9.52435e-07 sec) per iteration: 0.074409 sec for 78125 iterations 1.007 usec (1.00687e-06 sec) per iteration: 0.078662 sec for 78125 iterations mean: 0.978442 usec stddev: 0.018763 usec relative stddev: 1.92% RESULT TestHostSyscall: gn_trusted_mac_x86-64= {0.978442, 0.018763} us Measuring clock cycles: first runs (cycles): 3207 2754 2715 2718 2718 2721 2727 2730 2724 2721 ... slowest runs (cycles): ... 2754 2757 2760 2760 2763 2763 2766 2769 2775 3207 min: 2715 cycles q1: 2721 cycles median: 2739 cycles q3: 2751 cycles max: 3207 cycles RESULT TestHostSyscall_CycleCount: gn_trusted_mac_x86-64= {2739, 30} count Apparent clock speed: 2799 MHz TestSetjmpLongjmp: Measuring real time: 5.240 usec (5.24e-06 sec) per iteration: 0.000524 sec for 100 iterations 4.801 usec (4.8015e-06 sec) per iteration: 0.091627 sec for 19083 iterations 4.501 usec (4.50123e-06 sec) per iteration: 0.085897 sec for 19083 iterations 4.438 usec (4.43845e-06 sec) per iteration: 0.084699 sec for 19083 iterations 4.820 usec (4.81953e-06 sec) per iteration: 0.091971 sec for 19083 iterations 4.635 usec (4.63491e-06 sec) per iteration: 0.088448 sec for 19083 iterations mean: 4.639124 usec stddev: 0.153760 usec relative stddev: 3.31% RESULT TestSetjmpLongjmp: gn_trusted_mac_x86-64= {4.639124, 0.153760} us Measuring clock cycles: first runs (cycles): 12726 11667 11622 11625 11610 11625 11622 11625 11607 11616 ... slowest runs (cycles): ... 12825 12825 12831 12834 12891 12993 22605 49830 51015 51057 min: 11607 cycles q1: 11982 cycles median: 12798 cycles q3: 12816 cycles max: 51057 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_trusted_mac_x86-64= {12798, 834} count Apparent clock speed: 2759 MHz TestClockGetTime: Measuring real time: 0.080 usec (8e-08 sec) per iteration: 8e-06 sec for 100 iterations 0.076 usec (7.6e-08 sec) per iteration: 7.6e-05 sec for 1000 iterations 0.074 usec (7.37329e-08 sec) per iteration: 0.097017 sec for 1315789 iterations 0.071 usec (7.12493e-08 sec) per iteration: 0.093749 sec for 1315789 iterations 0.073 usec (7.25451e-08 sec) per iteration: 0.095454 sec for 1315789 iterations 0.074 usec (7.37056e-08 sec) per iteration: 0.096981 sec for 1315789 iterations 0.073 usec (7.33833e-08 sec) per iteration: 0.096557 sec for 1315789 iterations mean: 0.072923 usec stddev: 0.000941 usec relative stddev: 1.29% RESULT TestClockGetTime: gn_trusted_mac_x86-64= {0.072923, 0.000941} us Measuring clock cycles: first runs (cycles): 1284 222 213 210 210 210 210 213 210 213 ... slowest runs (cycles): ... 213 213 213 213 213 213 222 231 240 1284 min: 201 cycles q1: 210 cycles median: 210 cycles q3: 213 cycles max: 1284 cycles RESULT TestClockGetTime_CycleCount: gn_trusted_mac_x86-64= {210, 3} count Apparent clock speed: 2880 MHz TestMmapAnonymous: Measuring real time: 3.470 usec (3.47e-06 sec) per iteration: 0.000347 sec for 100 iterations 3.091 usec (3.09105e-06 sec) per iteration: 0.089078 sec for 28818 iterations 2.951 usec (2.95118e-06 sec) per iteration: 0.085047 sec for 28818 iterations 2.972 usec (2.97196e-06 sec) per iteration: 0.085646 sec for 28818 iterations 3.211 usec (3.21108e-06 sec) per iteration: 0.092537 sec for 28818 iterations 2.964 usec (2.96415e-06 sec) per iteration: 0.085421 sec for 28818 iterations mean: 3.037886 usec stddev: 0.100125 usec relative stddev: 3.30% RESULT TestMmapAnonymous: gn_trusted_mac_x86-64= {3.037886, 0.100125} us Measuring clock cycles: first runs (cycles): 12309 8169 7935 46872 8427 8430 8433 8445 9081 13110 ... slowest runs (cycles): ... 12498 12822 13008 13110 13158 13329 14976 15099 15456 46872 min: 7935 cycles q1: 8430 cycles median: 8463 cycles q3: 8553 cycles max: 46872 cycles RESULT TestMmapAnonymous_CycleCount: gn_trusted_mac_x86-64= {8463, 123} count Apparent clock speed: 2786 MHz TestAtomicIncrement: Measuring real time: 0.010 usec (1e-08 sec) per iteration: 1e-06 sec for 100 iterations 0.007 usec (7e-09 sec) per iteration: 7e-06 sec for 1000 iterations 0.007 usec (7.4e-09 sec) per iteration: 7.4e-05 sec for 10000 iterations 0.007 usec (7.19546e-09 sec) per iteration: 0.097236 sec for 13513513 iterations 0.007 usec (6.91389e-09 sec) per iteration: 0.093431 sec for 13513513 iterations 0.007 usec (7.02571e-09 sec) per iteration: 0.094942 sec for 13513513 iterations 0.007 usec (6.89569e-09 sec) per iteration: 0.093185 sec for 13513513 iterations 0.007 usec (7.0912e-09 sec) per iteration: 0.095827 sec for 13513513 iterations mean: 0.007024 usec stddev: 0.000112 usec relative stddev: 1.59% RESULT TestAtomicIncrement: gn_trusted_mac_x86-64= {0.007024, 0.000112} us Measuring clock cycles: first runs (cycles): 303 51 51 51 51 51 51 51 48 48 ... slowest runs (cycles): ... 48 51 51 51 51 51 51 51 66 303 min: 42 cycles q1: 45 cycles median: 48 cycles q3: 48 cycles max: 303 cycles RESULT TestAtomicIncrement_CycleCount: gn_trusted_mac_x86-64= {48, 3} count Apparent clock speed: 6833 MHz TestUncontendedMutexLock: Measuring real time: 0.350 usec (3.5e-07 sec) per iteration: 3.5e-05 sec for 100 iterations 0.027 usec (2.6579e-08 sec) per iteration: 0.007594 sec for 285714 iterations 0.027 usec (2.70305e-08 sec) per iteration: 0.007723 sec for 285714 iterations 0.027 usec (2.65195e-08 sec) per iteration: 0.007577 sec for 285714 iterations 0.026 usec (2.5683e-08 sec) per iteration: 0.007338 sec for 285714 iterations 0.027 usec (2.65895e-08 sec) per iteration: 0.007597 sec for 285714 iterations mean: 0.026480 usec stddev: 0.000439 usec relative stddev: 1.66% RESULT TestUncontendedMutexLock: gn_trusted_mac_x86-64= {0.026480, 0.000439} us Measuring clock cycles: first runs (cycles): 507 102 96 96 84 84 96 96 93 93 ... slowest runs (cycles): ... 96 96 96 96 96 96 96 102 111 507 min: 84 cycles q1: 87 cycles median: 93 cycles q3: 96 cycles max: 507 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_trusted_mac_x86-64= {93, 9} count Apparent clock speed: 3512 MHz TestCondvarSignalNoOp: Measuring real time: 0.110 usec (1.1e-07 sec) per iteration: 1.1e-05 sec for 100 iterations 0.014 usec (1.36851e-08 sec) per iteration: 0.012441 sec for 909090 iterations 0.013 usec (1.33859e-08 sec) per iteration: 0.012169 sec for 909090 iterations 0.014 usec (1.37346e-08 sec) per iteration: 0.012486 sec for 909090 iterations 0.013 usec (1.32781e-08 sec) per iteration: 0.012071 sec for 909090 iterations 0.014 usec (1.37104e-08 sec) per iteration: 0.012464 sec for 909090 iterations mean: 0.013559 usec stddev: 0.000189 usec relative stddev: 1.39% RESULT TestCondvarSignalNoOp: gn_trusted_mac_x86-64= {0.013559, 0.000189} us Measuring clock cycles: first runs (cycles): 513 75 57 57 57 57 57 57 57 57 ... slowest runs (cycles): ... 57 57 57 57 57 57 57 75 78 513 min: 57 cycles q1: 57 cycles median: 57 cycles q3: 57 cycles max: 513 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_trusted_mac_x86-64= {57, 0} count Apparent clock speed: 4204 MHz TestThreadCreateAndJoin: Measuring real time: 78.970 usec (7.897e-05 sec) per iteration: 0.007897 sec for 100 iterations 77.140 usec (7.71398e-05 sec) per iteration: 0.097659 sec for 1266 iterations 76.698 usec (7.66983e-05 sec) per iteration: 0.0971 sec for 1266 iterations 74.766 usec (7.47662e-05 sec) per iteration: 0.094654 sec for 1266 iterations 80.625 usec (8.06248e-05 sec) per iteration: 0.102071 sec for 1266 iterations 80.408 usec (8.04084e-05 sec) per iteration: 0.101797 sec for 1266 iterations mean: 77.927488 usec stddev: 2.260775 usec relative stddev: 2.90% RESULT TestThreadCreateAndJoin: gn_trusted_mac_x86-64= {77.927488, 2.260775} us Measuring clock cycles: first runs (cycles): 306918 164937 273033 309330 308316 155874 247548 259563 260925 145839 ... slowest runs (cycles): ... 256110 259290 259563 260925 263484 273033 273534 306918 308316 309330 min: 140268 cycles q1: 147336 cycles median: 237591 cycles q3: 246936 cycles max: 309330 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_trusted_mac_x86-64= {237591, 99600} count Apparent clock speed: 3049 MHz TestThreadWakeup: Measuring real time: 21.570 usec (2.157e-05 sec) per iteration: 0.002157 sec for 100 iterations 19.595 usec (1.95953e-05 sec) per iteration: 0.090844 sec for 4636 iterations 19.711 usec (1.97114e-05 sec) per iteration: 0.091382 sec for 4636 iterations 19.412 usec (1.9412e-05 sec) per iteration: 0.089994 sec for 4636 iterations 19.752 usec (1.97524e-05 sec) per iteration: 0.091572 sec for 4636 iterations 19.578 usec (1.95779e-05 sec) per iteration: 0.090763 sec for 4636 iterations mean: 19.609793 usec stddev: 0.119167 usec relative stddev: 0.61% RESULT TestThreadWakeup: gn_trusted_mac_x86-64= {19.609793, 0.119167} us Measuring clock cycles: first runs (cycles): 66750 53166 51660 52206 53388 85563 60054 54996 63852 55707 ... slowest runs (cycles): ... 61191 61632 62592 63795 63852 64860 66750 67128 68415 85563 min: 46413 cycles q1: 51411 cycles median: 51660 cycles q3: 52848 cycles max: 85563 cycles RESULT TestThreadWakeup_CycleCount: gn_trusted_mac_x86-64= {51660, 1437} count Apparent clock speed: 2634 MHz WARNING: should have taken less than 2.000000 secs [ OK ] nacl_newlib.run_trusted_performance_test (3860 ms) scons: done building targets. ********************************************************************** COMMAND EXECUTION REPORT ********************************************************************** 6 command_tester.py 1 doSizeCheck ********************************************************************** ENVIRONMENT USAGE REPORT ********************************************************************** 4 nacl-x86-64 3 opt-mac-x86-64 Command return code: 0