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

Running command: /b/s/w/ir/cache/vpython/4f3597/bin/python scons.py --verbose -k -j1 --mode=nacl,dbg-host platform=x86-64 large_tests scons: Reading SConscript files ... ====================================================================== SCONS ARGS:['scons.py', '--verbose', '-k', '-j1', '--mode=nacl,dbg-host', 'platform=x86-64', 'large_tests'] ====================================================================== ====================================================================== 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/4f3597/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 = 1537186175, usec = 570009 } Mon Sep 17 05:09:35 2018 ====================================================================== 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 /Applications/Xcode9.3.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/4f3597/bin/python tools/command_tester.py --name nacl_newlib.run_benchmark_test --time_warning 10 --time_error 100 --perf_env_description 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 scons-out/dbg-mac-x86-64/staging/sel_ldr -- scons-out/nacl-x86-64/obj/tests/benchmark/benchmark_test.nexe x86-64_nnacl_newlib_static [ RUN ] nacl_newlib.run_benchmark_test scons-out/dbg-mac-x86-64/staging/sel_ldr -- scons-out/nacl-x86-64/obj/tests/benchmark/benchmark_test.nexe x86-64_nnacl_newlib_static [39781,2586280832:14:39:32.162893] Native Client module will be loaded at base address 0x00006c2700000000 Running suite of 1 benchmarks: Running Benchmark: Life (SIMD version)... RESULT BenchmarkLife: x86-64_nnacl_newlib_static= {0.077220, 0.005200} seconds --------------------------------------------------------------- Done running benchmark suite. [ OK ] nacl_newlib.run_benchmark_test (929 ms) /b/s/w/ir/cache/vpython/4f3597/bin/python tools/command_tester.py --name nacl_newlib.run_clock_cputime_test --time_warning 60 --time_error 600 --perf_env_description 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 scons-out/dbg-mac-x86-64/staging/sel_ldr -- scons-out/nacl-x86-64/obj/tests/clock/clock_test.nexe -c [ RUN ] nacl_newlib.run_clock_cputime_test scons-out/dbg-mac-x86-64/staging/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 (67910 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: x86-64_nnacl_newlib_static= 528.080 KB RESULT hello_world_size.out: ZIPPED_x86-64_nnacl_newlib_static= 187.899 KB /b/s/w/ir/cache/vpython/4f3597/bin/python tools/command_tester.py --name nacl_newlib.run_performance_test --time_warning 10 --time_error 100 --perf_env_description 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 scons-out/dbg-mac-x86-64/staging/sel_ldr -e -- scons-out/nacl-x86-64/obj/tests/performance/performance_test.nexe x86-64_nnacl_newlib_static [ RUN ] nacl_newlib.run_performance_test scons-out/dbg-mac-x86-64/staging/sel_ldr -e -- scons-out/nacl-x86-64/obj/tests/performance/performance_test.nexe x86-64_nnacl_newlib_static [39787,2586280832:14:39:46.693472] Native Client module will be loaded at base address 0x00007b6b00000000 TestNull: Measuring real time: 0.013 usec (1.323e-08 sec) per iteration: 1.323e-06 sec for 100 iterations 0.002 usec (2.479e-09 sec) per iteration: 2.479e-06 sec for 1000 iterations 0.002 usec (2.0412e-09 sec) per iteration: 2.0412e-05 sec for 10000 iterations 0.002 usec (2.01009e-09 sec) per iteration: 0.0984758 sec for 48990789 iterations 0.002 usec (2.00961e-09 sec) per iteration: 0.0984525 sec for 48990789 iterations 0.002 usec (2.00645e-09 sec) per iteration: 0.0982978 sec for 48990789 iterations 0.002 usec (2.00381e-09 sec) per iteration: 0.0981683 sec for 48990789 iterations 0.002 usec (1.99164e-09 sec) per iteration: 0.0975721 sec for 48990789 iterations mean: 0.002004 usec stddev: 0.000007 usec relative stddev: 0.34% RESULT TestNull: x86-64_nnacl_newlib_static= {0.002004, 0.000007} us Measuring clock cycles: first runs (cycles): 285 18 21 21 30 30 30 30 21 21 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 30 285 min: 18 cycles q1: 21 cycles median: 21 cycles q3: 30 cycles max: 285 cycles RESULT TestNull_CycleCount: x86-64_nnacl_newlib_static= {21, 9} count Apparent clock speed: 10477 MHz TestNaClSyscall: Measuring real time: 0.231 usec (2.3059e-07 sec) per iteration: 2.3059e-05 sec for 100 iterations 0.223 usec (2.23189e-07 sec) per iteration: 0.0967904 sec for 433670 iterations 0.224 usec (2.24076e-07 sec) per iteration: 0.0971752 sec for 433670 iterations 0.223 usec (2.22569e-07 sec) per iteration: 0.0965217 sec for 433670 iterations 0.224 usec (2.23567e-07 sec) per iteration: 0.0969543 sec for 433670 iterations 0.223 usec (2.22929e-07 sec) per iteration: 0.0966774 sec for 433670 iterations mean: 0.223266 usec stddev: 0.000520 usec relative stddev: 0.23% RESULT TestNaClSyscall: x86-64_nnacl_newlib_static= {0.223266, 0.000520} us Measuring clock cycles: first runs (cycles): 1077 507 483 492 483 489 483 498 483 489 ... slowest runs (cycles): ... 501 501 501 501 504 504 504 504 507 1077 min: 483 cycles q1: 489 cycles median: 489 cycles q3: 492 cycles max: 1077 cycles RESULT TestNaClSyscall_CycleCount: x86-64_nnacl_newlib_static= {489, 3} count Apparent clock speed: 2190 MHz TestSetjmpLongjmp: Measuring real time: 0.019 usec (1.868e-08 sec) per iteration: 1.868e-06 sec for 100 iterations 0.013 usec (1.2613e-08 sec) per iteration: 1.2613e-05 sec for 1000 iterations 0.014 usec (1.35096e-08 sec) per iteration: 0.107108 sec for 7928327 iterations 0.012 usec (1.20324e-08 sec) per iteration: 0.0953972 sec for 7928327 iterations 0.013 usec (1.29654e-08 sec) per iteration: 0.102794 sec for 7928327 iterations 0.013 usec (1.32441e-08 sec) per iteration: 0.105004 sec for 7928327 iterations 0.012 usec (1.20918e-08 sec) per iteration: 0.0958678 sec for 7928327 iterations mean: 0.012769 usec stddev: 0.000602 usec relative stddev: 4.72% RESULT TestSetjmpLongjmp: x86-64_nnacl_newlib_static= {0.012769, 0.000602} us Measuring clock cycles: first runs (cycles): 465 57 33 33 24 24 21 33 33 33 ... slowest runs (cycles): ... 33 33 33 33 33 33 33 33 57 465 min: 21 cycles q1: 24 cycles median: 30 cycles q3: 33 cycles max: 465 cycles RESULT TestSetjmpLongjmp_CycleCount: x86-64_nnacl_newlib_static= {30, 9} count Apparent clock speed: 2349 MHz TestClockGetTime: Measuring real time: 0.306 usec (3.0561e-07 sec) per iteration: 3.0561e-05 sec for 100 iterations 0.294 usec (2.94058e-07 sec) per iteration: 0.09622 sec for 327214 iterations 0.298 usec (2.98358e-07 sec) per iteration: 0.0976268 sec for 327214 iterations 0.299 usec (2.99211e-07 sec) per iteration: 0.0979061 sec for 327214 iterations 0.298 usec (2.98215e-07 sec) per iteration: 0.0975801 sec for 327214 iterations 0.298 usec (2.9795e-07 sec) per iteration: 0.0974934 sec for 327214 iterations mean: 0.297558 usec stddev: 0.001800 usec relative stddev: 0.61% RESULT TestClockGetTime: x86-64_nnacl_newlib_static= {0.297558, 0.001800} us Measuring clock cycles: first runs (cycles): 2787 855 813 885 813 831 819 822 831 822 ... slowest runs (cycles): ... 831 831 831 855 870 873 882 885 918 2787 min: 813 cycles q1: 816 cycles median: 819 cycles q3: 822 cycles max: 2787 cycles RESULT TestClockGetTime_CycleCount: x86-64_nnacl_newlib_static= {819, 6} count Apparent clock speed: 2752 MHz TestTlsVariable: Measuring real time: 0.015 usec (1.469e-08 sec) per iteration: 1.469e-06 sec for 100 iterations 0.007 usec (6.512e-09 sec) per iteration: 6.512e-06 sec for 1000 iterations 0.006 usec (6.0454e-09 sec) per iteration: 6.0454e-05 sec for 10000 iterations 0.006 usec (6.03403e-09 sec) per iteration: 0.0998119 sec for 16541502 iterations 0.006 usec (6.0191e-09 sec) per iteration: 0.099565 sec for 16541502 iterations 0.006 usec (6.01926e-09 sec) per iteration: 0.0995676 sec for 16541502 iterations 0.006 usec (6.03254e-09 sec) per iteration: 0.0997873 sec for 16541502 iterations 0.006 usec (6.03502e-09 sec) per iteration: 0.0998282 sec for 16541502 iterations mean: 0.006028 usec stddev: 0.000007 usec relative stddev: 0.12% RESULT TestTlsVariable: x86-64_nnacl_newlib_static= {0.006028, 0.000007} us Measuring clock cycles: first runs (cycles): 384 66 30 30 30 30 30 21 21 21 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 66 384 min: 21 cycles q1: 21 cycles median: 21 cycles q3: 30 cycles max: 384 cycles RESULT TestTlsVariable_CycleCount: x86-64_nnacl_newlib_static= {21, 9} count Apparent clock speed: 3484 MHz TestMmapAnonymous: Measuring real time: 10.209 usec (1.02093e-05 sec) per iteration: 0.00102093 sec for 100 iterations 9.765 usec (9.7652e-06 sec) per iteration: 0.0956502 sec for 9795 iterations 9.622 usec (9.62221e-06 sec) per iteration: 0.0942496 sec for 9795 iterations 10.036 usec (1.0036e-05 sec) per iteration: 0.0983028 sec for 9795 iterations 9.932 usec (9.93189e-06 sec) per iteration: 0.0972829 sec for 9795 iterations 9.955 usec (9.95502e-06 sec) per iteration: 0.0975094 sec for 9795 iterations mean: 9.862069 usec stddev: 0.148787 usec relative stddev: 1.51% RESULT TestMmapAnonymous: x86-64_nnacl_newlib_static= {9.862069, 0.148787} us Measuring clock cycles: first runs (cycles): 39102 27495 27441 26829 26958 26889 26763 26625 26727 26844 ... slowest runs (cycles): ... 27135 27192 27273 27405 27441 27459 27495 29799 39102 47046 min: 26409 cycles q1: 26664 cycles median: 26766 cycles q3: 26940 cycles max: 47046 cycles RESULT TestMmapAnonymous_CycleCount: x86-64_nnacl_newlib_static= {26766, 276} count Apparent clock speed: 2714 MHz TestAtomicIncrement: Measuring real time: 0.016 usec (1.601e-08 sec) per iteration: 1.601e-06 sec for 100 iterations 0.010 usec (1.0097e-08 sec) per iteration: 1.0097e-05 sec for 1000 iterations 0.010 usec (9.68009e-09 sec) per iteration: 0.0958709 sec for 9903931 iterations 0.010 usec (9.6902e-09 sec) per iteration: 0.095971 sec for 9903931 iterations 0.010 usec (9.74172e-09 sec) per iteration: 0.0964813 sec for 9903931 iterations 0.010 usec (9.71537e-09 sec) per iteration: 0.0962203 sec for 9903931 iterations 0.010 usec (9.68889e-09 sec) per iteration: 0.0959581 sec for 9903931 iterations mean: 0.009703 usec stddev: 0.000023 usec relative stddev: 0.23% RESULT TestAtomicIncrement: x86-64_nnacl_newlib_static= {0.009703, 0.000023} us Measuring clock cycles: first runs (cycles): 282 48 51 51 48 51 48 51 48 51 ... slowest runs (cycles): ... 51 51 51 51 51 51 51 51 51 282 min: 39 cycles q1: 48 cycles median: 48 cycles q3: 51 cycles max: 282 cycles RESULT TestAtomicIncrement_CycleCount: x86-64_nnacl_newlib_static= {48, 3} count Apparent clock speed: 4947 MHz TestUncontendedMutexLock: Measuring real time: 0.030 usec (2.964e-08 sec) per iteration: 2.964e-06 sec for 100 iterations 0.023 usec (2.344e-08 sec) per iteration: 2.344e-05 sec for 1000 iterations 0.024 usec (2.42112e-08 sec) per iteration: 0.10329 sec for 4266211 iterations 0.023 usec (2.30372e-08 sec) per iteration: 0.0982818 sec for 4266211 iterations 0.023 usec (2.3095e-08 sec) per iteration: 0.0985281 sec for 4266211 iterations 0.023 usec (2.3413e-08 sec) per iteration: 0.0998847 sec for 4266211 iterations 0.025 usec (2.47018e-08 sec) per iteration: 0.105383 sec for 4266211 iterations mean: 0.023692 usec stddev: 0.000656 usec relative stddev: 2.77% RESULT TestUncontendedMutexLock: x86-64_nnacl_newlib_static= {0.023692, 0.000656} us Measuring clock cycles: first runs (cycles): 636 156 102 105 99 105 105 99 105 111 ... slowest runs (cycles): ... 111 111 114 114 114 123 123 126 156 636 min: 87 cycles q1: 99 cycles median: 105 cycles q3: 108 cycles max: 636 cycles RESULT TestUncontendedMutexLock_CycleCount: x86-64_nnacl_newlib_static= {105, 9} count Apparent clock speed: 4432 MHz TestCondvarSignalNoOp: Measuring real time: 0.634 usec (6.3449e-07 sec) per iteration: 6.3449e-05 sec for 100 iterations 0.249 usec (2.49063e-07 sec) per iteration: 0.0392538 sec for 157606 iterations 0.312 usec (3.11632e-07 sec) per iteration: 0.0491151 sec for 157606 iterations 0.247 usec (2.46999e-07 sec) per iteration: 0.0389285 sec for 157606 iterations 0.238 usec (2.38396e-07 sec) per iteration: 0.0375727 sec for 157606 iterations 0.244 usec (2.43514e-07 sec) per iteration: 0.0383792 sec for 157606 iterations mean: 0.257921 usec stddev: 0.027098 usec relative stddev: 10.51% RESULT TestCondvarSignalNoOp: x86-64_nnacl_newlib_static= {0.257921, 0.027098} us Measuring clock cycles: first runs (cycles): 2070 651 633 645 645 645 645 660 642 648 ... slowest runs (cycles): ... 651 651 651 651 651 651 660 732 735 2070 min: 633 cycles q1: 645 cycles median: 648 cycles q3: 648 cycles max: 2070 cycles RESULT TestCondvarSignalNoOp_CycleCount: x86-64_nnacl_newlib_static= {648, 3} count Apparent clock speed: 2512 MHz TestThreadCreateAndJoin: Measuring real time: 96.005 usec (9.60047e-05 sec) per iteration: 0.00960047 sec for 100 iterations 92.728 usec (9.27276e-05 sec) per iteration: 0.0965295 sec for 1041 iterations 96.203 usec (9.62032e-05 sec) per iteration: 0.100148 sec for 1041 iterations 92.368 usec (9.23678e-05 sec) per iteration: 0.0961549 sec for 1041 iterations 94.972 usec (9.49716e-05 sec) per iteration: 0.0988655 sec for 1041 iterations 95.822 usec (9.58219e-05 sec) per iteration: 0.0997506 sec for 1041 iterations mean: 94.418433 usec stddev: 1.582725 usec relative stddev: 1.68% RESULT TestThreadCreateAndJoin: x86-64_nnacl_newlib_static= {94.418433, 1.582725} us Measuring clock cycles: first runs (cycles): 297702 273300 274671 277560 269226 282672 261027 292467 282951 308229 ... slowest runs (cycles): ... 312441 312711 313083 314583 315366 321459 321735 322665 328437 372648 min: 231393 cycles q1: 254607 cycles median: 289962 cycles q3: 300420 cycles max: 372648 cycles RESULT TestThreadCreateAndJoin_CycleCount: x86-64_nnacl_newlib_static= {289962, 45813} count Apparent clock speed: 3071 MHz TestThreadWakeup: Measuring real time: 38.620 usec (3.86204e-05 sec) per iteration: 0.00386204 sec for 100 iterations 31.974 usec (3.19744e-05 sec) per iteration: 0.0827818 sec for 2589 iterations 32.541 usec (3.25407e-05 sec) per iteration: 0.0842479 sec for 2589 iterations 32.368 usec (3.23679e-05 sec) per iteration: 0.0838005 sec for 2589 iterations 33.415 usec (3.34146e-05 sec) per iteration: 0.0865105 sec for 2589 iterations 33.189 usec (3.31885e-05 sec) per iteration: 0.0859251 sec for 2589 iterations mean: 32.697239 usec stddev: 0.531310 usec relative stddev: 1.62% RESULT TestThreadWakeup: x86-64_nnacl_newlib_static= {32.697239, 0.531310} us Measuring clock cycles: first runs (cycles): 95946 90981 94611 96921 119124 99999 87012 232434 101673 89040 ... slowest runs (cycles): ... 94611 95946 96294 96921 99999 101673 114105 114216 119124 232434 min: 86958 cycles q1: 88023 cycles median: 88593 cycles q3: 89274 cycles max: 232434 cycles RESULT TestThreadWakeup_CycleCount: x86-64_nnacl_newlib_static= {88593, 1251} count Apparent clock speed: 2709 MHz TestCatchingFault: Measuring real time: 37.827 usec (3.78268e-05 sec) per iteration: 0.00378268 sec for 100 iterations 33.073 usec (3.30732e-05 sec) per iteration: 0.0874125 sec for 2643 iterations 33.108 usec (3.31079e-05 sec) per iteration: 0.0875043 sec for 2643 iterations 33.204 usec (3.32043e-05 sec) per iteration: 0.087759 sec for 2643 iterations 32.818 usec (3.28179e-05 sec) per iteration: 0.0867377 sec for 2643 iterations 33.022 usec (3.30222e-05 sec) per iteration: 0.0872777 sec for 2643 iterations mean: 33.045110 usec stddev: 0.128244 usec relative stddev: 0.39% RESULT TestCatchingFault: x86-64_nnacl_newlib_static= {33.045110, 0.128244} us Measuring clock cycles: first runs (cycles): 107379 89952 88485 88803 97389 114675 156714 155244 112434 112728 ... slowest runs (cycles): ... 112434 112728 114675 127629 131412 150402 155244 156714 162012 178764 min: 87960 cycles q1: 88521 cycles median: 88956 cycles q3: 89562 cycles max: 178764 cycles RESULT TestCatchingFault_CycleCount: x86-64_nnacl_newlib_static= {88956, 1041} count Apparent clock speed: 2692 MHz TestThreadCreateAndJoinAfterSettingFaultHandler: Measuring real time: 97.910 usec (9.79104e-05 sec) per iteration: 0.00979104 sec for 100 iterations 106.362 usec (0.000106362 sec) per iteration: 0.108596 sec for 1021 iterations 101.255 usec (0.000101255 sec) per iteration: 0.103381 sec for 1021 iterations 96.305 usec (9.63047e-05 sec) per iteration: 0.0983271 sec for 1021 iterations 92.009 usec (9.20092e-05 sec) per iteration: 0.0939414 sec for 1021 iterations 100.760 usec (0.00010076 sec) per iteration: 0.102876 sec for 1021 iterations mean: 99.338260 usec stddev: 4.856952 usec relative stddev: 4.89% RESULT TestThreadCreateAndJoinAfterSettingFaultHandler: x86-64_nnacl_newlib_static= {99.338260, 4.856952} us Measuring clock cycles: first runs (cycles): 391323 275139 295926 350370 279414 269316 242676 257595 270633 273402 ... slowest runs (cycles): ... 264558 264765 269316 270633 273402 275139 279414 295926 350370 391323 min: 232017 cycles q1: 246375 cycles median: 248010 cycles q3: 252363 cycles max: 391323 cycles RESULT TestThreadCreateAndJoinAfterSettingFaultHandler_CycleCount: x86-64_nnacl_newlib_static= {248010, 5988} count Apparent clock speed: 2497 MHz [ OK ] nacl_newlib.run_performance_test (6620 ms) /b/s/w/ir/cache/vpython/4f3597/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 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 (9080 ms) /b/s/w/ir/cache/vpython/4f3597/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 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 (1990 ms) /b/s/w/ir/cache/vpython/4f3597/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 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 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 trusted_mac_x86-64 TestNull: Measuring real time: 0.000 usec (0 sec) per iteration: 0 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.65604e-09 sec) per iteration: 0.098372 sec for 37037037 iterations 0.003 usec (3.38996e-09 sec) per iteration: 0.125554 sec for 37037037 iterations 0.003 usec (3.15743e-09 sec) per iteration: 0.116942 sec for 37037037 iterations 0.003 usec (2.75295e-09 sec) per iteration: 0.101961 sec for 37037037 iterations 0.003 usec (2.6757e-09 sec) per iteration: 0.0991 sec for 37037037 iterations mean: 0.002926 usec stddev: 0.000295 usec relative stddev: 10.07% RESULT TestNull: trusted_mac_x86-64= {0.002926, 0.000295} us Measuring clock cycles: first runs (cycles): 243 24 21 18 21 21 21 18 30 30 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 48 243 min: 18 cycles q1: 21 cycles median: 21 cycles q3: 30 cycles max: 243 cycles RESULT TestNull_CycleCount: trusted_mac_x86-64= {21, 9} count Apparent clock speed: 7176 MHz TestHostSyscall: Measuring real time: 1.250 usec (1.25e-06 sec) per iteration: 0.000125 sec for 100 iterations 1.079 usec (1.07936e-06 sec) per iteration: 0.086348 sec for 79999 iterations 1.063 usec (1.06294e-06 sec) per iteration: 0.085034 sec for 79999 iterations 1.082 usec (1.08198e-06 sec) per iteration: 0.086557 sec for 79999 iterations 1.071 usec (1.0712e-06 sec) per iteration: 0.085695 sec for 79999 iterations 1.183 usec (1.1831e-06 sec) per iteration: 0.094647 sec for 79999 iterations mean: 1.095716 usec stddev: 0.044199 usec relative stddev: 4.03% RESULT TestHostSyscall: trusted_mac_x86-64= {1.095716, 0.044199} us Measuring clock cycles: first runs (cycles): 3261 2856 2814 2829 2823 2814 2808 2814 2808 2814 ... slowest runs (cycles): ... 2859 2859 2862 2862 2862 2862 2862 2865 2970 3261 min: 2808 cycles q1: 2814 cycles median: 2847 cycles q3: 2856 cycles max: 3261 cycles RESULT TestHostSyscall_CycleCount: trusted_mac_x86-64= {2847, 42} count Apparent clock speed: 2598 MHz TestSetjmpLongjmp: Measuring real time: 5.540 usec (5.54e-06 sec) per iteration: 0.000554 sec for 100 iterations 5.737 usec (5.73679e-06 sec) per iteration: 0.103549 sec for 18050 iterations 5.244 usec (5.24432e-06 sec) per iteration: 0.09466 sec for 18050 iterations 4.973 usec (4.97296e-06 sec) per iteration: 0.089762 sec for 18050 iterations 5.034 usec (5.03374e-06 sec) per iteration: 0.090859 sec for 18050 iterations 4.869 usec (4.8687e-06 sec) per iteration: 0.08788 sec for 18050 iterations mean: 5.171302 usec stddev: 0.308200 usec relative stddev: 5.96% RESULT TestSetjmpLongjmp: trusted_mac_x86-64= {5.171302, 0.308200} us Measuring clock cycles: first runs (cycles): 14547 13224 13203 13197 13194 13197 13191 13206 13197 13194 ... slowest runs (cycles): ... 13266 13269 13269 13272 13275 13332 13389 13431 13503 14547 min: 13188 cycles q1: 13200 cycles median: 13248 cycles q3: 13260 cycles max: 14547 cycles RESULT TestSetjmpLongjmp_CycleCount: trusted_mac_x86-64= {13248, 60} count Apparent clock speed: 2562 MHz TestClockGetTime: Measuring real time: 0.080 usec (8e-08 sec) per iteration: 8e-06 sec for 100 iterations 0.077 usec (7.7e-08 sec) per iteration: 7.7e-05 sec for 1000 iterations 0.078 usec (7.76946e-08 sec) per iteration: 0.100902 sec for 1298701 iterations 0.078 usec (7.76576e-08 sec) per iteration: 0.100854 sec for 1298701 iterations 0.083 usec (8.34749e-08 sec) per iteration: 0.108409 sec for 1298701 iterations 0.078 usec (7.80526e-08 sec) per iteration: 0.101367 sec for 1298701 iterations 0.089 usec (8.90413e-08 sec) per iteration: 0.115638 sec for 1298701 iterations mean: 0.081184 usec stddev: 0.004503 usec relative stddev: 5.55% RESULT TestClockGetTime: trusted_mac_x86-64= {0.081184, 0.004503} us Measuring clock cycles: first runs (cycles): 2451 273 288 255 255 255 264 270 255 264 ... slowest runs (cycles): ... 291 291 294 297 300 300 312 345 408 2451 min: 237 cycles q1: 261 cycles median: 270 cycles q3: 279 cycles max: 2451 cycles RESULT TestClockGetTime_CycleCount: trusted_mac_x86-64= {270, 18} count Apparent clock speed: 3326 MHz TestMmapAnonymous: Measuring real time: 5.000 usec (5e-06 sec) per iteration: 0.0005 sec for 100 iterations 4.036 usec (4.03625e-06 sec) per iteration: 0.080721 sec for 19999 iterations 3.295 usec (3.29511e-06 sec) per iteration: 0.065899 sec for 19999 iterations 3.088 usec (3.08835e-06 sec) per iteration: 0.061764 sec for 19999 iterations 3.498 usec (3.49752e-06 sec) per iteration: 0.069947 sec for 19999 iterations 3.135 usec (3.13461e-06 sec) per iteration: 0.062689 sec for 19999 iterations mean: 3.410371 usec stddev: 0.344194 usec relative stddev: 10.09% RESULT TestMmapAnonymous: trusted_mac_x86-64= {3.410371, 0.344194} us Measuring clock cycles: first runs (cycles): 11409 8520 8346 8331 8364 8349 8262 8343 8343 8328 ... slowest runs (cycles): ... 8403 8406 8412 8412 8421 8424 8424 8430 8520 11409 min: 8229 cycles q1: 8286 cycles median: 8352 cycles q3: 8379 cycles max: 11409 cycles RESULT TestMmapAnonymous_CycleCount: trusted_mac_x86-64= {8352, 93} count Apparent clock speed: 2449 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.7128e-09 sec) per iteration: 0.097128 sec for 10000000 iterations 0.010 usec (9.7017e-09 sec) per iteration: 0.097017 sec for 10000000 iterations 0.010 usec (9.7221e-09 sec) per iteration: 0.097221 sec for 10000000 iterations 0.010 usec (9.7601e-09 sec) per iteration: 0.097601 sec for 10000000 iterations 0.010 usec (9.7539e-09 sec) per iteration: 0.097539 sec for 10000000 iterations mean: 0.009730 usec stddev: 0.000023 usec relative stddev: 0.24% RESULT TestAtomicIncrement: trusted_mac_x86-64= {0.009730, 0.000023} us Measuring clock cycles: first runs (cycles): 378 60 60 60 54 54 54 54 57 54 ... slowest runs (cycles): ... 57 57 57 57 60 60 60 60 87 378 min: 54 cycles q1: 54 cycles median: 54 cycles q3: 57 cycles max: 378 cycles RESULT TestAtomicIncrement_CycleCount: trusted_mac_x86-64= {54, 3} count Apparent clock speed: 5550 MHz TestUncontendedMutexLock: Measuring real time: 0.220 usec (2.2e-07 sec) per iteration: 2.2e-05 sec for 100 iterations 0.027 usec (2.65034e-08 sec) per iteration: 0.012047 sec for 454545 iterations 0.026 usec (2.64682e-08 sec) per iteration: 0.012031 sec for 454545 iterations 0.026 usec (2.64022e-08 sec) per iteration: 0.012001 sec for 454545 iterations 0.026 usec (2.64176e-08 sec) per iteration: 0.012008 sec for 454545 iterations 0.026 usec (2.6411e-08 sec) per iteration: 0.012005 sec for 454545 iterations mean: 0.026441 usec stddev: 0.000039 usec relative stddev: 0.15% RESULT TestUncontendedMutexLock: trusted_mac_x86-64= {0.026441, 0.000039} us Measuring clock cycles: first runs (cycles): 825 111 93 102 99 102 102 102 105 93 ... slowest runs (cycles): ... 102 102 102 102 102 105 105 111 132 825 min: 90 cycles q1: 102 cycles median: 102 cycles q3: 102 cycles max: 825 cycles RESULT TestUncontendedMutexLock_CycleCount: trusted_mac_x86-64= {102, 0} count Apparent clock speed: 3858 MHz TestCondvarSignalNoOp: Measuring real time: 0.110 usec (1.1e-07 sec) per iteration: 1.1e-05 sec for 100 iterations 0.017 usec (1.68058e-08 sec) per iteration: 0.015278 sec for 909090 iterations 0.017 usec (1.67299e-08 sec) per iteration: 0.015209 sec for 909090 iterations 0.017 usec (1.67057e-08 sec) per iteration: 0.015187 sec for 909090 iterations 0.017 usec (1.66122e-08 sec) per iteration: 0.015102 sec for 909090 iterations 0.017 usec (1.66991e-08 sec) per iteration: 0.015181 sec for 909090 iterations mean: 0.016711 usec stddev: 0.000062 usec relative stddev: 0.37% RESULT TestCondvarSignalNoOp: trusted_mac_x86-64= {0.016711, 0.000062} us Measuring clock cycles: first runs (cycles): 834 87 69 69 69 78 78 69 69 69 ... slowest runs (cycles): ... 78 78 78 78 78 78 78 84 87 834 min: 66 cycles q1: 69 cycles median: 69 cycles q3: 78 cycles max: 834 cycles RESULT TestCondvarSignalNoOp_CycleCount: trusted_mac_x86-64= {69, 9} count Apparent clock speed: 4129 MHz TestThreadCreateAndJoin: Measuring real time: 96.320 usec (9.632e-05 sec) per iteration: 0.009632 sec for 100 iterations 89.032 usec (8.90318e-05 sec) per iteration: 0.092415 sec for 1038 iterations 87.430 usec (8.74297e-05 sec) per iteration: 0.090752 sec for 1038 iterations 90.532 usec (9.05318e-05 sec) per iteration: 0.093972 sec for 1038 iterations 93.442 usec (9.34422e-05 sec) per iteration: 0.096993 sec for 1038 iterations 86.877 usec (8.68767e-05 sec) per iteration: 0.090178 sec for 1038 iterations mean: 89.462428 usec stddev: 2.365828 usec relative stddev: 2.64% RESULT TestThreadCreateAndJoin: trusted_mac_x86-64= {89.462428, 2.365828} us Measuring clock cycles: first runs (cycles): 241668 239346 176703 170013 272196 186393 337314 180330 322374 303966 ... slowest runs (cycles): ... 311013 315264 317850 322002 322167 322374 322812 332298 334719 337314 min: 143349 cycles q1: 180330 cycles median: 241668 cycles q3: 275811 cycles max: 337314 cycles RESULT TestThreadCreateAndJoin_CycleCount: trusted_mac_x86-64= {241668, 95481} count Apparent clock speed: 2701 MHz TestThreadWakeup: Measuring real time: 22.900 usec (2.29e-05 sec) per iteration: 0.00229 sec for 100 iterations 23.838 usec (2.38383e-05 sec) per iteration: 0.104078 sec for 4366 iterations 22.623 usec (2.26235e-05 sec) per iteration: 0.098774 sec for 4366 iterations 22.933 usec (2.29333e-05 sec) per iteration: 0.100127 sec for 4366 iterations 23.519 usec (2.35192e-05 sec) per iteration: 0.102685 sec for 4366 iterations 23.923 usec (2.39235e-05 sec) per iteration: 0.10445 sec for 4366 iterations mean: 23.367568 usec stddev: 0.509098 usec relative stddev: 2.18% RESULT TestThreadWakeup: trusted_mac_x86-64= {23.367568, 0.509098} us Measuring clock cycles: first runs (cycles): 61665 54483 53514 53907 53376 53445 54342 53523 53307 54267 ... slowest runs (cycles): ... 74376 74772 77343 77727 78789 83742 85935 88326 112395 129063 min: 52935 cycles q1: 54483 cycles median: 59103 cycles q3: 64962 cycles max: 129063 cycles RESULT TestThreadWakeup_CycleCount: trusted_mac_x86-64= {59103, 10479} count Apparent clock speed: 2529 MHz WARNING: should have taken less than 2.000000 secs [ OK ] nacl_newlib.run_trusted_performance_test (4019 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