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 = 1552669774, usec = 152375 } Fri Mar 15 10:09:34 2019 ====================================================================== The following environments have been configured ====================================================================== NACL_BUILD_FAMILY: UNTRUSTED BUILD_TYPE: nacl TARGET_ROOT: /b/s/w/ir/k/native_client/scons-out/nacl-x86-64 OBJ_ROOT: /b/s/w/ir/k/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/k/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang ASPPCOM: /b/s/w/ir/k/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/k/native_client/scons-out/nacl-x86-64/include -I/b/s/w/ir/k -c -o UNKNOWN COMPILER NACL_BUILD_FAMILY: TRUSTED BUILD_TYPE: opt-mac TARGET_ROOT: /b/s/w/ir/k/native_client/scons-out/opt-mac-x86-64 OBJ_ROOT: /b/s/w/ir/k/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/k/third_party/llvm-build/Release+Asserts/bin/clang ASPPCOM: /b/s/w/ir/k/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/k -c -o UNKNOWN COMPILER NACL_BUILD_FAMILY: UNTRUSTED_IRT BUILD_TYPE: nacl_irt TARGET_ROOT: /b/s/w/ir/k/native_client/scons-out/nacl_irt-x86-64 OBJ_ROOT: /b/s/w/ir/k/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/k/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang ASPPCOM: /b/s/w/ir/k/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/k/native_client/scons-out/nacl_irt-x86-64/include -I/b/s/w/ir/k -I/b/s/w/ir/k/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/k/native_client/scons-out/nacl-x86-64/test_results/benchmark_test.out /b/s/w/ir/k/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/k/out_64/sel_ldr -- scons-out/nacl-x86-64/obj/tests/benchmark/benchmark_test.nexe gn_x86-64_nnacl_newlib_static [31420,3051619200:13:14:13.936274] Native Client module will be loaded at base address 0x0000452c00000000 Running suite of 1 benchmarks: Running Benchmark: Life (SIMD version)... RESULT BenchmarkLife: gn_x86-64_nnacl_newlib_static= {0.064940, 0.001540} seconds --------------------------------------------------------------- Done running benchmark suite. [ OK ] nacl_newlib.run_benchmark_test (850 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/k/native_client/scons-out/nacl-x86-64/test_results/clock_cputime_test.out /b/s/w/ir/k/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/k/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 (66230 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= 524.896 KB RESULT hello_world_size.out: ZIPPED_gn_x86-64_nnacl_newlib_static= 187.825 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/k/native_client/scons-out/nacl-x86-64/test_results/performance_test.out /b/s/w/ir/k/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/k/out_64/sel_ldr -e -- scons-out/nacl-x86-64/obj/tests/performance/performance_test.nexe gn_x86-64_nnacl_newlib_static [31425,3051619200:13:14:28.140316] Native Client module will be loaded at base address 0x000063b200000000 TestNull: Measuring real time: 0.007 usec (6.99e-09 sec) per iteration: 6.99e-07 sec for 100 iterations 0.002 usec (2.267e-09 sec) per iteration: 2.267e-06 sec for 1000 iterations 0.002 usec (2.027e-09 sec) per iteration: 2.027e-05 sec for 10000 iterations 0.002 usec (1.98674e-09 sec) per iteration: 0.0980137 sec for 49333991 iterations 0.002 usec (2.02545e-09 sec) per iteration: 0.0999234 sec for 49333991 iterations 0.002 usec (1.99236e-09 sec) per iteration: 0.0982909 sec for 49333991 iterations 0.002 usec (1.98099e-09 sec) per iteration: 0.0977303 sec for 49333991 iterations 0.002 usec (2.04874e-09 sec) per iteration: 0.101073 sec for 49333991 iterations mean: 0.002007 usec stddev: 0.000026 usec relative stddev: 1.30% RESULT TestNull: gn_x86-64_nnacl_newlib_static= {0.002007, 0.000026} us Measuring clock cycles: first runs (cycles): 258 18 21 36 21 21 21 21 21 21 ... slowest runs (cycles): ... 36 36 36 36 36 36 36 36 36 258 min: 18 cycles q1: 21 cycles median: 21 cycles q3: 21 cycles max: 258 cycles RESULT TestNull_CycleCount: gn_x86-64_nnacl_newlib_static= {21, 0} count Apparent clock speed: 10464 MHz TestNaClSyscall: Measuring real time: 0.158 usec (1.5765e-07 sec) per iteration: 1.5765e-05 sec for 100 iterations 0.157 usec (1.57316e-07 sec) per iteration: 0.0997882 sec for 634316 iterations 0.160 usec (1.59681e-07 sec) per iteration: 0.101288 sec for 634316 iterations 0.158 usec (1.57635e-07 sec) per iteration: 0.0999902 sec for 634316 iterations 0.162 usec (1.6197e-07 sec) per iteration: 0.10274 sec for 634316 iterations 0.154 usec (1.53681e-07 sec) per iteration: 0.097482 sec for 634316 iterations mean: 0.158056 usec stddev: 0.002751 usec relative stddev: 1.74% RESULT TestNaClSyscall: gn_x86-64_nnacl_newlib_static= {0.158056, 0.002751} us Measuring clock cycles: first runs (cycles): 756 300 285 279 279 279 294 294 294 294 ... slowest runs (cycles): ... 297 297 297 297 297 297 300 300 303 756 min: 279 cycles q1: 279 cycles median: 294 cycles q3: 297 cycles max: 756 cycles RESULT TestNaClSyscall_CycleCount: gn_x86-64_nnacl_newlib_static= {294, 18} count Apparent clock speed: 1860 MHz TestSetjmpLongjmp: Measuring real time: 0.016 usec (1.611e-08 sec) per iteration: 1.611e-06 sec for 100 iterations 0.012 usec (1.2412e-08 sec) per iteration: 1.2412e-05 sec for 1000 iterations 0.012 usec (1.23653e-08 sec) per iteration: 0.0996241 sec for 8056719 iterations 0.012 usec (1.1842e-08 sec) per iteration: 0.0954073 sec for 8056719 iterations 0.012 usec (1.20586e-08 sec) per iteration: 0.0971524 sec for 8056719 iterations 0.012 usec (1.19905e-08 sec) per iteration: 0.0966038 sec for 8056719 iterations 0.012 usec (1.18509e-08 sec) per iteration: 0.0954796 sec for 8056719 iterations mean: 0.012021 usec stddev: 0.000191 usec relative stddev: 1.59% RESULT TestSetjmpLongjmp: gn_x86-64_nnacl_newlib_static= {0.012021, 0.000191} us Measuring clock cycles: first runs (cycles): 423 54 57 57 54 24 24 33 33 33 ... slowest runs (cycles): ... 33 33 33 33 33 54 54 57 57 423 min: 24 cycles q1: 24 cycles median: 33 cycles q3: 33 cycles max: 423 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_x86-64_nnacl_newlib_static= {33, 9} count Apparent clock speed: 2745 MHz TestClockGetTime: Measuring real time: 0.161 usec (1.6089e-07 sec) per iteration: 1.6089e-05 sec for 100 iterations 0.158 usec (1.57948e-07 sec) per iteration: 0.0981715 sec for 621542 iterations 0.157 usec (1.57202e-07 sec) per iteration: 0.0977078 sec for 621542 iterations 0.157 usec (1.57174e-07 sec) per iteration: 0.09769 sec for 621542 iterations 0.157 usec (1.57363e-07 sec) per iteration: 0.097808 sec for 621542 iterations 0.157 usec (1.56862e-07 sec) per iteration: 0.0974962 sec for 621542 iterations mean: 0.157310 usec stddev: 0.000358 usec relative stddev: 0.23% RESULT TestClockGetTime: gn_x86-64_nnacl_newlib_static= {0.157310, 0.000358} us Measuring clock cycles: first runs (cycles): 1668 468 435 432 441 435 447 435 444 435 ... slowest runs (cycles): ... 444 444 444 444 447 447 447 447 468 1668 min: 432 cycles q1: 435 cycles median: 435 cycles q3: 438 cycles max: 1668 cycles RESULT TestClockGetTime_CycleCount: gn_x86-64_nnacl_newlib_static= {435, 3} count Apparent clock speed: 2765 MHz TestTlsVariable: Measuring real time: 0.010 usec (9.81e-09 sec) per iteration: 9.81e-07 sec for 100 iterations 0.006 usec (6.284e-09 sec) per iteration: 6.284e-06 sec for 1000 iterations 0.006 usec (6.0291e-09 sec) per iteration: 6.0291e-05 sec for 10000 iterations 0.006 usec (6.0675e-09 sec) per iteration: 0.100637 sec for 16586223 iterations 0.006 usec (6.06841e-09 sec) per iteration: 0.100652 sec for 16586223 iterations 0.006 usec (6.09104e-09 sec) per iteration: 0.101027 sec for 16586223 iterations 0.006 usec (6.19015e-09 sec) per iteration: 0.102671 sec for 16586223 iterations 0.006 usec (6.0612e-09 sec) per iteration: 0.100532 sec for 16586223 iterations mean: 0.006096 usec stddev: 0.000048 usec relative stddev: 0.79% RESULT TestTlsVariable: gn_x86-64_nnacl_newlib_static= {0.006096, 0.000048} us Measuring clock cycles: first runs (cycles): 354 72 21 21 24 24 21 18 21 33 ... slowest runs (cycles): ... 36 36 36 36 36 36 36 36 72 354 min: 18 cycles q1: 18 cycles median: 21 cycles q3: 21 cycles max: 354 cycles RESULT TestTlsVariable_CycleCount: gn_x86-64_nnacl_newlib_static= {21, 3} count Apparent clock speed: 3445 MHz TestMmapAnonymous: Measuring real time: 8.893 usec (8.89319e-06 sec) per iteration: 0.000889319 sec for 100 iterations 8.712 usec (8.71189e-06 sec) per iteration: 0.0979565 sec for 11244 iterations 8.675 usec (8.67524e-06 sec) per iteration: 0.0975444 sec for 11244 iterations 8.649 usec (8.64872e-06 sec) per iteration: 0.0972463 sec for 11244 iterations 8.646 usec (8.64568e-06 sec) per iteration: 0.097212 sec for 11244 iterations 8.755 usec (8.75497e-06 sec) per iteration: 0.0984409 sec for 11244 iterations mean: 8.687301 usec stddev: 0.041353 usec relative stddev: 0.48% RESULT TestMmapAnonymous: gn_x86-64_nnacl_newlib_static= {8.687301, 0.041353} us Measuring clock cycles: first runs (cycles): 33084 24117 23178 23001 22926 23037 22908 22917 22944 22956 ... slowest runs (cycles): ... 23046 23067 23067 23073 23076 23115 23178 23181 24117 33084 min: 22815 cycles q1: 22896 cycles median: 22956 cycles q3: 23004 cycles max: 33084 cycles RESULT TestMmapAnonymous_CycleCount: gn_x86-64_nnacl_newlib_static= {22956, 108} count Apparent clock speed: 2642 MHz TestAtomicIncrement: Measuring real time: 0.014 usec (1.434e-08 sec) per iteration: 1.434e-06 sec for 100 iterations 0.010 usec (9.904e-09 sec) per iteration: 9.904e-06 sec for 1000 iterations 0.010 usec (9.69e-09 sec) per iteration: 9.69e-05 sec for 10000 iterations 0.010 usec (9.74495e-09 sec) per iteration: 0.100567 sec for 10319917 iterations 0.010 usec (9.73209e-09 sec) per iteration: 0.100434 sec for 10319917 iterations 0.010 usec (9.76996e-09 sec) per iteration: 0.100825 sec for 10319917 iterations 0.010 usec (1.0129e-08 sec) per iteration: 0.104531 sec for 10319917 iterations 0.010 usec (9.64149e-09 sec) per iteration: 0.0994994 sec for 10319917 iterations mean: 0.009804 usec stddev: 0.000168 usec relative stddev: 1.72% RESULT TestAtomicIncrement: gn_x86-64_nnacl_newlib_static= {0.009804, 0.000168} us Measuring clock cycles: first runs (cycles): 228 51 51 48 42 51 51 51 51 51 ... slowest runs (cycles): ... 51 51 51 51 51 51 51 51 51 228 min: 42 cycles q1: 51 cycles median: 51 cycles q3: 51 cycles max: 228 cycles RESULT TestAtomicIncrement_CycleCount: gn_x86-64_nnacl_newlib_static= {51, 0} count Apparent clock speed: 5202 MHz TestUncontendedMutexLock: Measuring real time: 0.028 usec (2.752e-08 sec) per iteration: 2.752e-06 sec for 100 iterations 0.023 usec (2.3244e-08 sec) per iteration: 2.3244e-05 sec for 1000 iterations 0.023 usec (2.30035e-08 sec) per iteration: 0.0989654 sec for 4302185 iterations 0.024 usec (2.35097e-08 sec) per iteration: 0.101143 sec for 4302185 iterations 0.023 usec (2.33359e-08 sec) per iteration: 0.100395 sec for 4302185 iterations 0.023 usec (2.29226e-08 sec) per iteration: 0.0986174 sec for 4302185 iterations 0.023 usec (2.28979e-08 sec) per iteration: 0.0985108 sec for 4302185 iterations mean: 0.023134 usec stddev: 0.000245 usec relative stddev: 1.06% RESULT TestUncontendedMutexLock: gn_x86-64_nnacl_newlib_static= {0.023134, 0.000245} us Measuring clock cycles: first runs (cycles): 429 111 81 81 90 90 90 90 90 90 ... slowest runs (cycles): ... 90 90 90 90 90 90 90 90 111 429 min: 81 cycles q1: 81 cycles median: 90 cycles q3: 90 cycles max: 429 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_x86-64_nnacl_newlib_static= {90, 9} count Apparent clock speed: 3890 MHz TestCondvarSignalNoOp: Measuring real time: 0.274 usec (2.735e-07 sec) per iteration: 2.735e-05 sec for 100 iterations 0.153 usec (1.53175e-07 sec) per iteration: 0.0560055 sec for 365630 iterations 0.159 usec (1.58981e-07 sec) per iteration: 0.0581281 sec for 365630 iterations 0.158 usec (1.58377e-07 sec) per iteration: 0.0579075 sec for 365630 iterations 0.158 usec (1.58281e-07 sec) per iteration: 0.0578724 sec for 365630 iterations 0.161 usec (1.60902e-07 sec) per iteration: 0.0588307 sec for 365630 iterations mean: 0.157943 usec stddev: 0.002564 usec relative stddev: 1.62% RESULT TestCondvarSignalNoOp: gn_x86-64_nnacl_newlib_static= {0.157943, 0.002564} us Measuring clock cycles: first runs (cycles): 1554 438 432 429 432 432 432 432 432 432 ... slowest runs (cycles): ... 435 435 435 435 435 435 438 444 462 1554 min: 429 cycles q1: 432 cycles median: 432 cycles q3: 432 cycles max: 1554 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_x86-64_nnacl_newlib_static= {432, 0} count Apparent clock speed: 2735 MHz TestThreadCreateAndJoin: Measuring real time: 65.818 usec (6.58176e-05 sec) per iteration: 0.00658176 sec for 100 iterations 64.691 usec (6.46907e-05 sec) per iteration: 0.0982652 sec for 1519 iterations 63.566 usec (6.35658e-05 sec) per iteration: 0.0965564 sec for 1519 iterations 63.498 usec (6.34981e-05 sec) per iteration: 0.0964536 sec for 1519 iterations 64.375 usec (6.43752e-05 sec) per iteration: 0.097786 sec for 1519 iterations 63.876 usec (6.38759e-05 sec) per iteration: 0.0970275 sec for 1519 iterations mean: 64.001140 usec stddev: 0.463405 usec relative stddev: 0.72% RESULT TestThreadCreateAndJoin: gn_x86-64_nnacl_newlib_static= {64.001140, 0.463405} us Measuring clock cycles: first runs (cycles): 172596 182688 223050 251091 199959 187446 211563 180786 178401 179670 ... slowest runs (cycles): ... 206523 210633 211563 211707 212892 215481 222072 223050 235725 251091 min: 154929 cycles q1: 171591 cycles median: 172884 cycles q3: 180786 cycles max: 251091 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_x86-64_nnacl_newlib_static= {172884, 9195} count Apparent clock speed: 2701 MHz TestThreadWakeup: Measuring real time: 32.129 usec (3.21291e-05 sec) per iteration: 0.0032129 sec for 100 iterations 31.680 usec (3.16796e-05 sec) per iteration: 0.0985869 sec for 3112 iterations 31.832 usec (3.18315e-05 sec) per iteration: 0.0990597 sec for 3112 iterations 31.791 usec (3.1791e-05 sec) per iteration: 0.0989335 sec for 3112 iterations 31.485 usec (3.1485e-05 sec) per iteration: 0.0979813 sec for 3112 iterations 31.689 usec (3.16893e-05 sec) per iteration: 0.0986172 sec for 3112 iterations mean: 31.695278 usec stddev: 0.120185 usec relative stddev: 0.38% RESULT TestThreadWakeup: gn_x86-64_nnacl_newlib_static= {31.695278, 0.120185} us Measuring clock cycles: first runs (cycles): 87714 92037 76029 84141 100392 103128 120090 94149 95325 85839 ... slowest runs (cycles): ... 93420 94149 95325 100392 102840 103128 103986 109257 120090 146580 min: 56085 cycles q1: 84453 cycles median: 85638 cycles q3: 87228 cycles max: 146580 cycles RESULT TestThreadWakeup_CycleCount: gn_x86-64_nnacl_newlib_static= {85638, 2775} count Apparent clock speed: 2702 MHz TestCatchingFault: Measuring real time: 34.538 usec (3.45384e-05 sec) per iteration: 0.00345384 sec for 100 iterations 31.060 usec (3.10604e-05 sec) per iteration: 0.0899199 sec for 2895 iterations 31.036 usec (3.10359e-05 sec) per iteration: 0.0898488 sec for 2895 iterations 31.787 usec (3.17874e-05 sec) per iteration: 0.0920244 sec for 2895 iterations 30.560 usec (3.05604e-05 sec) per iteration: 0.0884724 sec for 2895 iterations 31.291 usec (3.12915e-05 sec) per iteration: 0.0905888 sec for 2895 iterations mean: 31.147111 usec stddev: 0.398716 usec relative stddev: 1.28% RESULT TestCatchingFault: gn_x86-64_nnacl_newlib_static= {31.147111, 0.398716} us Measuring clock cycles: first runs (cycles): 127977 110727 135372 100728 127209 133041 113184 106605 103698 92010 ... slowest runs (cycles): ... 105963 106605 110727 113184 121821 127209 127977 133041 135372 143508 min: 80400 cycles q1: 81474 cycles median: 82809 cycles q3: 84138 cycles max: 143508 cycles RESULT TestCatchingFault_CycleCount: gn_x86-64_nnacl_newlib_static= {82809, 2664} count Apparent clock speed: 2659 MHz TestThreadCreateAndJoinAfterSettingFaultHandler: Measuring real time: 65.780 usec (6.57798e-05 sec) per iteration: 0.00657798 sec for 100 iterations 63.976 usec (6.39763e-05 sec) per iteration: 0.097244 sec for 1520 iterations 64.172 usec (6.41724e-05 sec) per iteration: 0.097542 sec for 1520 iterations 65.140 usec (6.514e-05 sec) per iteration: 0.0990127 sec for 1520 iterations 64.767 usec (6.47673e-05 sec) per iteration: 0.0984462 sec for 1520 iterations 64.581 usec (6.45812e-05 sec) per iteration: 0.0981634 sec for 1520 iterations mean: 64.527410 usec stddev: 0.416029 usec relative stddev: 0.64% RESULT TestThreadCreateAndJoinAfterSettingFaultHandler: gn_x86-64_nnacl_newlib_static= {64.527410, 0.416029} us Measuring clock cycles: first runs (cycles): 169380 179073 203085 162039 182952 170628 165417 174153 166851 170550 ... slowest runs (cycles): ... 185358 185895 191706 199239 203085 204831 206409 214572 227859 252855 min: 162039 cycles q1: 169146 cycles median: 170700 cycles q3: 173292 cycles max: 252855 cycles RESULT TestThreadCreateAndJoinAfterSettingFaultHandler_CycleCount: gn_x86-64_nnacl_newlib_static= {170700, 4146} count Apparent clock speed: 2645 MHz [ OK ] nacl_newlib.run_performance_test (6570 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python /b/s/w/ir/k/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/k/native_client/scons-out/opt-mac-x86-64/test_results/nacl_clock_cputime_test.out /b/s/w/ir/k/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/k/native_client/scons-out/opt-mac-x86-64/obj/src/shared/platform/nacl_clock_test -c [ OK ] nacl_newlib.run_nacl_clock_cputime_test (1530 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python /b/s/w/ir/k/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/k/native_client/scons-out/opt-mac-x86-64/test_results/nacl_interval_multi_reg_test.out /b/s/w/ir/k/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/k/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 (460 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python /b/s/w/ir/k/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/k/native_client/scons-out/opt-mac-x86-64/test_results/performance_test.out /b/s/w/ir/k/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/k/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.6e-09 sec) per iteration: 2.6e-05 sec for 10000 iterations 0.003 usec (2.67972e-09 sec) per iteration: 0.103066 sec for 38461538 iterations 0.003 usec (2.67491e-09 sec) per iteration: 0.102881 sec for 38461538 iterations 0.003 usec (2.60832e-09 sec) per iteration: 0.10032 sec for 38461538 iterations 0.003 usec (2.66656e-09 sec) per iteration: 0.10256 sec for 38461538 iterations 0.003 usec (2.66037e-09 sec) per iteration: 0.102322 sec for 38461538 iterations mean: 0.002658 usec stddev: 0.000026 usec relative stddev: 0.97% RESULT TestNull: gn_trusted_mac_x86-64= {0.002658, 0.000026} us Measuring clock cycles: first runs (cycles): 240 30 30 21 21 21 21 21 30 30 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 30 240 min: 21 cycles q1: 21 cycles median: 21 cycles q3: 30 cycles max: 240 cycles RESULT TestNull_CycleCount: gn_trusted_mac_x86-64= {21, 9} count Apparent clock speed: 7901 MHz TestHostSyscall: Measuring real time: 1.140 usec (1.14e-06 sec) per iteration: 0.000114 sec for 100 iterations 1.003 usec (1.0035e-06 sec) per iteration: 0.088026 sec for 87719 iterations 0.991 usec (9.90869e-07 sec) per iteration: 0.086918 sec for 87719 iterations 1.002 usec (1.00229e-06 sec) per iteration: 0.08792 sec for 87719 iterations 1.003 usec (1.00261e-06 sec) per iteration: 0.087948 sec for 87719 iterations 1.005 usec (1.00503e-06 sec) per iteration: 0.08816 sec for 87719 iterations mean: 1.000860 usec stddev: 0.005085 usec relative stddev: 0.51% RESULT TestHostSyscall: gn_trusted_mac_x86-64= {1.000860, 0.005085} us Measuring clock cycles: first runs (cycles): 3045 2751 2676 2679 2676 2685 2685 2688 2688 2691 ... slowest runs (cycles): ... 2721 2721 2721 2721 2724 2724 2730 2736 2751 3045 min: 2673 cycles q1: 2685 cycles median: 2709 cycles q3: 2709 cycles max: 3045 cycles RESULT TestHostSyscall_CycleCount: gn_trusted_mac_x86-64= {2709, 24} count Apparent clock speed: 2707 MHz TestSetjmpLongjmp: Measuring real time: 5.340 usec (5.34e-06 sec) per iteration: 0.000534 sec for 100 iterations 4.893 usec (4.8925e-06 sec) per iteration: 0.091617 sec for 18726 iterations 5.074 usec (5.07364e-06 sec) per iteration: 0.095009 sec for 18726 iterations 5.030 usec (5.03044e-06 sec) per iteration: 0.0942 sec for 18726 iterations 5.041 usec (5.04069e-06 sec) per iteration: 0.094392 sec for 18726 iterations 5.098 usec (5.09789e-06 sec) per iteration: 0.095463 sec for 18726 iterations mean: 5.027032 usec stddev: 0.071399 usec relative stddev: 1.42% RESULT TestSetjmpLongjmp: gn_trusted_mac_x86-64= {5.027032, 0.071399} us Measuring clock cycles: first runs (cycles): 15003 13968 13914 13920 13908 13902 13908 13902 13920 13911 ... slowest runs (cycles): ... 13968 13968 13971 13971 13971 13971 13971 13971 13971 15003 min: 13899 cycles q1: 13914 cycles median: 13947 cycles q3: 13959 cycles max: 15003 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_trusted_mac_x86-64= {13947, 45} count Apparent clock speed: 2774 MHz TestClockGetTime: Measuring real time: 0.070 usec (7e-08 sec) per iteration: 7e-06 sec for 100 iterations 0.075 usec (7.5e-08 sec) per iteration: 7.5e-05 sec for 1000 iterations 0.076 usec (7.56638e-08 sec) per iteration: 0.100885 sec for 1333333 iterations 0.076 usec (7.59113e-08 sec) per iteration: 0.101215 sec for 1333333 iterations 0.076 usec (7.64723e-08 sec) per iteration: 0.101963 sec for 1333333 iterations 0.076 usec (7.6404e-08 sec) per iteration: 0.101872 sec for 1333333 iterations 0.077 usec (7.73873e-08 sec) per iteration: 0.103183 sec for 1333333 iterations mean: 0.076368 usec stddev: 0.000593 usec relative stddev: 0.78% RESULT TestClockGetTime: gn_trusted_mac_x86-64= {0.076368, 0.000593} us Measuring clock cycles: first runs (cycles): 1032 225 210 210 204 210 210 201 210 210 ... slowest runs (cycles): ... 213 213 213 213 213 213 213 219 225 1032 min: 201 cycles q1: 210 cycles median: 210 cycles q3: 213 cycles max: 1032 cycles RESULT TestClockGetTime_CycleCount: gn_trusted_mac_x86-64= {210, 3} count Apparent clock speed: 2750 MHz TestMmapAnonymous: Measuring real time: 3.560 usec (3.56e-06 sec) per iteration: 0.000356 sec for 100 iterations 3.187 usec (3.1868e-06 sec) per iteration: 0.089514 sec for 28089 iterations 3.195 usec (3.1947e-06 sec) per iteration: 0.089736 sec for 28089 iterations 3.203 usec (3.20346e-06 sec) per iteration: 0.089982 sec for 28089 iterations 3.239 usec (3.23928e-06 sec) per iteration: 0.090988 sec for 28089 iterations 3.259 usec (3.25943e-06 sec) per iteration: 0.091554 sec for 28089 iterations mean: 3.216733 usec stddev: 0.027887 usec relative stddev: 0.87% RESULT TestMmapAnonymous: gn_trusted_mac_x86-64= {3.216733, 0.027887} us Measuring clock cycles: first runs (cycles): 12300 8841 8889 8748 8805 8883 8748 8733 8784 8961 ... slowest runs (cycles): ... 8826 8841 8859 8883 8889 8892 8901 8901 8961 12300 min: 8718 cycles q1: 8745 cycles median: 8754 cycles q3: 8775 cycles max: 12300 cycles RESULT TestMmapAnonymous_CycleCount: gn_trusted_mac_x86-64= {8754, 30} count Apparent clock speed: 2721 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.3e-09 sec) per iteration: 7.3e-05 sec for 10000 iterations 0.007 usec (7.34256e-09 sec) per iteration: 0.100583 sec for 13698630 iterations 0.007 usec (7.31153e-09 sec) per iteration: 0.100158 sec for 13698630 iterations 0.007 usec (7.32314e-09 sec) per iteration: 0.100317 sec for 13698630 iterations 0.008 usec (7.62266e-09 sec) per iteration: 0.10442 sec for 13698630 iterations 0.007 usec (7.34132e-09 sec) per iteration: 0.100566 sec for 13698630 iterations mean: 0.007388 usec stddev: 0.000118 usec relative stddev: 1.59% RESULT TestAtomicIncrement: gn_trusted_mac_x86-64= {0.007388, 0.000118} us Measuring clock cycles: first runs (cycles): 354 54 51 54 51 54 51 54 48 48 ... slowest runs (cycles): ... 48 51 51 51 54 54 54 54 63 354 min: 48 cycles q1: 48 cycles median: 48 cycles q3: 48 cycles max: 354 cycles RESULT TestAtomicIncrement_CycleCount: gn_trusted_mac_x86-64= {48, 0} count Apparent clock speed: 6497 MHz TestUncontendedMutexLock: Measuring real time: 0.210 usec (2.1e-07 sec) per iteration: 2.1e-05 sec for 100 iterations 0.027 usec (2.65293e-08 sec) per iteration: 0.012633 sec for 476190 iterations 0.027 usec (2.65713e-08 sec) per iteration: 0.012653 sec for 476190 iterations 0.027 usec (2.65503e-08 sec) per iteration: 0.012643 sec for 476190 iterations 0.026 usec (2.64936e-08 sec) per iteration: 0.012616 sec for 476190 iterations 0.027 usec (2.65251e-08 sec) per iteration: 0.012631 sec for 476190 iterations mean: 0.026534 usec stddev: 0.000026 usec relative stddev: 0.10% RESULT TestUncontendedMutexLock: gn_trusted_mac_x86-64= {0.026534, 0.000026} us Measuring clock cycles: first runs (cycles): 375 105 84 84 96 96 93 93 87 87 ... slowest runs (cycles): ... 96 96 96 96 96 96 96 105 114 375 min: 84 cycles q1: 87 cycles median: 93 cycles q3: 96 cycles max: 375 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_trusted_mac_x86-64= {93, 9} count Apparent clock speed: 3505 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.37214e-08 sec) per iteration: 0.012474 sec for 909090 iterations 0.014 usec (1.36961e-08 sec) per iteration: 0.012451 sec for 909090 iterations 0.014 usec (1.37896e-08 sec) per iteration: 0.012536 sec for 909090 iterations 0.014 usec (1.37566e-08 sec) per iteration: 0.012506 sec for 909090 iterations 0.014 usec (1.37247e-08 sec) per iteration: 0.012477 sec for 909090 iterations mean: 0.013738 usec stddev: 0.000032 usec relative stddev: 0.24% RESULT TestCondvarSignalNoOp: gn_trusted_mac_x86-64= {0.013738, 0.000032} us Measuring clock cycles: first runs (cycles): 549 75 60 60 63 63 63 72 63 63 ... slowest runs (cycles): ... 72 72 72 72 72 72 72 75 84 549 min: 60 cycles q1: 60 cycles median: 63 cycles q3: 63 cycles max: 549 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_trusted_mac_x86-64= {63, 3} count Apparent clock speed: 4586 MHz TestThreadCreateAndJoin: Measuring real time: 86.940 usec (8.694e-05 sec) per iteration: 0.008694 sec for 100 iterations 80.291 usec (8.02913e-05 sec) per iteration: 0.092335 sec for 1150 iterations 79.697 usec (7.96965e-05 sec) per iteration: 0.091651 sec for 1150 iterations 81.103 usec (8.11026e-05 sec) per iteration: 0.093268 sec for 1150 iterations 79.491 usec (7.94913e-05 sec) per iteration: 0.091415 sec for 1150 iterations 79.758 usec (7.97583e-05 sec) per iteration: 0.091722 sec for 1150 iterations mean: 80.068000 usec stddev: 0.580826 usec relative stddev: 0.73% RESULT TestThreadCreateAndJoin: gn_trusted_mac_x86-64= {80.068000, 0.580826} us Measuring clock cycles: first runs (cycles): 254775 247587 205401 245166 134139 274731 163296 160797 257814 278667 ... slowest runs (cycles): ... 257814 262833 266124 266238 267165 269334 274731 278667 279663 307863 min: 134139 cycles q1: 209082 cycles median: 238050 cycles q3: 246195 cycles max: 307863 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_trusted_mac_x86-64= {238050, 37113} count Apparent clock speed: 2973 MHz TestThreadWakeup: Measuring real time: 24.130 usec (2.413e-05 sec) per iteration: 0.002413 sec for 100 iterations 21.866 usec (2.18663e-05 sec) per iteration: 0.090614 sec for 4144 iterations 22.070 usec (2.20702e-05 sec) per iteration: 0.091459 sec for 4144 iterations 22.326 usec (2.23265e-05 sec) per iteration: 0.092521 sec for 4144 iterations 21.829 usec (2.18292e-05 sec) per iteration: 0.09046 sec for 4144 iterations 21.791 usec (2.1791e-05 sec) per iteration: 0.090302 sec for 4144 iterations mean: 21.976641 usec stddev: 0.199768 usec relative stddev: 0.91% RESULT TestThreadWakeup: gn_trusted_mac_x86-64= {21.976641, 0.199768} us Measuring clock cycles: first runs (cycles): 71223 72558 64962 74508 53628 50916 69489 79491 119592 66279 ... slowest runs (cycles): ... 72417 72558 72765 72837 74280 74508 78168 79491 80922 119592 min: 50916 cycles q1: 52254 cycles median: 53025 cycles q3: 54864 cycles max: 119592 cycles RESULT TestThreadWakeup_CycleCount: gn_trusted_mac_x86-64= {53025, 2610} count Apparent clock speed: 2413 MHz WARNING: should have taken less than 2.000000 secs [ OK ] nacl_newlib.run_trusted_performance_test (4030 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