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

Running command: /b/s/w/ir/cache/vpython/7c7ecd/bin/python scons.py --verbose -k -j1 --mode=nacl,dbg-host platform=x86-64 --clang large_tests scons: Reading SConscript files ... ====================================================================== SCONS ARGS:['scons.py', '--verbose', '-k', '-j1', '--mode=nacl,dbg-host', 'platform=x86-64', '--clang', '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/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 = 1547621684, usec = 967389 } Tue Jan 15 22:54:44 2019 ====================================================================== The following environments have been configured ====================================================================== NACL_BUILD_FAMILY: UNTRUSTED BUILD_TYPE: nacl TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/obj BUILD_TYPE_DESCRIPTION: NaCl module build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang ASPPCOM: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_GNU_SOURCE=1 -D_POSIX_C_SOURCE=199506 -D_XOPEN_SOURCE=600 -DDYNAMIC_ANNOTATIONS_ENABLED=1 -DDYNAMIC_ANNOTATIONS_PREFIX=NACL_ -DNACL_BUILD_ARCH=x86 -DNACL_BUILD_SUBARCH=64 -I/b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/include -I/b/s/w/ir/kitchen-workdir -c -o UNKNOWN COMPILER NACL_BUILD_FAMILY: TRUSTED BUILD_TYPE: dbg-mac TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj BUILD_TYPE_DESCRIPTION: MacOS dbg build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/third_party/llvm-build/Release+Asserts/bin/clang ASPPCOM: /b/s/w/ir/kitchen-workdir/third_party/llvm-build/Release+Asserts/bin/clang -isysroot /b/s/w/ir/cache/osx_sdk/XCode.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX10.13.sdk -mmacosx-version-min=10.6 -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_DEBUG -I/b/s/w/ir/kitchen-workdir -c -o UNKNOWN COMPILER NACL_BUILD_FAMILY: UNTRUSTED_IRT BUILD_TYPE: nacl_irt TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64/obj BUILD_TYPE_DESCRIPTION: NaCl IRT build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang ASPPCOM: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_GNU_SOURCE=1 -D_POSIX_C_SOURCE=199506 -D_XOPEN_SOURCE=600 -DDYNAMIC_ANNOTATIONS_ENABLED=1 -DDYNAMIC_ANNOTATIONS_PREFIX=NACL_ -DNACL_BUILD_ARCH=x86 -DNACL_BUILD_SUBARCH=64 -I/b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64/include -I/b/s/w/ir/kitchen-workdir -I/b/s/w/ir/kitchen-workdir/native_client/src/untrusted/pthread -c -o UNKNOWN COMPILER *** BROKEN run_ncval_annotate_test *** BROKEN run_gdb_invalid_memory_test *** BROKEN run_nanosleep_test *** BROKEN run_timefuncs_test *** BROKEN run_raw_timefuncs_test *** BROKEN run_main_thread_pthread_exit_test2 *** BROKEN run_overflowinline_test *** BROKEN run_stack_frame_noopt_frame_test *** BROKEN run_stack_frame_noopt_noframe_test *** BROKEN run_stack_frame_opt_frame_test *** BROKEN run_stack_frame_opt_noframe_test *** BROKEN run_vla_test *** BROKEN run_nacl_sync_cond_test SKIPPING test text_overlaps_rodata SKIPPING test text_overlaps_data There are 13 broken tests. ====================================================================== B U I L D - O U T P U T: ====================================================================== scons: done reading SConscript files. scons: Building targets ... /b/s/w/ir/cache/vpython/7c7ecd/bin/python tools/command_tester.py --name nacl_newlib.run_benchmark_test --time_warning 10 --time_error 100 --perf_env_description 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 [32544,2906624896:09:39:47.985906] Native Client module will be loaded at base address 0x0000587700000000 Running suite of 1 benchmarks: Running Benchmark: Life (SIMD version)... RESULT BenchmarkLife: x86-64_nnacl_newlib_static= {0.077100, 0.004770} seconds --------------------------------------------------------------- Done running benchmark suite. [ OK ] nacl_newlib.run_benchmark_test (929 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 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 (66490 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/7c7ecd/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 [32552,2906624896:09:40:02.296538] Native Client module will be loaded at base address 0x00004c1500000000 TestNull: Measuring real time: 0.009 usec (8.74e-09 sec) per iteration: 8.74e-07 sec for 100 iterations 0.002 usec (2.413e-09 sec) per iteration: 2.413e-06 sec for 1000 iterations 0.002 usec (2.0402e-09 sec) per iteration: 2.0402e-05 sec for 10000 iterations 0.002 usec (2.02146e-09 sec) per iteration: 0.0990817 sec for 49014802 iterations 0.002 usec (2.01334e-09 sec) per iteration: 0.0986834 sec for 49014802 iterations 0.002 usec (2.01373e-09 sec) per iteration: 0.0987025 sec for 49014802 iterations 0.002 usec (2.01006e-09 sec) per iteration: 0.0985228 sec for 49014802 iterations 0.002 usec (2.01671e-09 sec) per iteration: 0.0988486 sec for 49014802 iterations mean: 0.002015 usec stddev: 0.000004 usec relative stddev: 0.19% RESULT TestNull: x86-64_nnacl_newlib_static= {0.002015, 0.000004} us Measuring clock cycles: first runs (cycles): 417 21 21 21 21 18 30 33 30 30 ... slowest runs (cycles): ... 33 33 33 33 33 33 33 33 36 417 min: 18 cycles q1: 21 cycles median: 24 cycles q3: 30 cycles max: 417 cycles RESULT TestNull_CycleCount: x86-64_nnacl_newlib_static= {24, 9} count Apparent clock speed: 11910 MHz TestNaClSyscall: Measuring real time: 0.266 usec (2.6561e-07 sec) per iteration: 2.6561e-05 sec for 100 iterations 0.226 usec (2.25726e-07 sec) per iteration: 0.0849838 sec for 376491 iterations 0.224 usec (2.23873e-07 sec) per iteration: 0.0842862 sec for 376491 iterations 0.224 usec (2.23985e-07 sec) per iteration: 0.0843283 sec for 376491 iterations 0.224 usec (2.23705e-07 sec) per iteration: 0.0842229 sec for 376491 iterations 0.224 usec (2.23946e-07 sec) per iteration: 0.0843138 sec for 376491 iterations mean: 0.224247 usec stddev: 0.000746 usec relative stddev: 0.33% RESULT TestNaClSyscall: x86-64_nnacl_newlib_static= {0.224247, 0.000746} us Measuring clock cycles: first runs (cycles): 1005 504 486 501 489 489 489 489 489 489 ... slowest runs (cycles): ... 498 498 498 498 501 501 501 501 504 1005 min: 486 cycles q1: 489 cycles median: 489 cycles q3: 489 cycles max: 1005 cycles RESULT TestNaClSyscall_CycleCount: x86-64_nnacl_newlib_static= {489, 0} count Apparent clock speed: 2181 MHz TestSetjmpLongjmp: Measuring real time: 0.024 usec (2.399e-08 sec) per iteration: 2.399e-06 sec for 100 iterations 0.015 usec (1.4578e-08 sec) per iteration: 1.4578e-05 sec for 1000 iterations 0.012 usec (1.21448e-08 sec) per iteration: 0.0833092 sec for 6859651 iterations 0.012 usec (1.22037e-08 sec) per iteration: 0.083713 sec for 6859651 iterations 0.012 usec (1.22239e-08 sec) per iteration: 0.083852 sec for 6859651 iterations 0.012 usec (1.21453e-08 sec) per iteration: 0.0833124 sec for 6859651 iterations 0.012 usec (1.21207e-08 sec) per iteration: 0.0831435 sec for 6859651 iterations mean: 0.012168 usec stddev: 0.000039 usec relative stddev: 0.32% RESULT TestSetjmpLongjmp: x86-64_nnacl_newlib_static= {0.012168, 0.000039} us Measuring clock cycles: first runs (cycles): 564 33 33 24 27 24 33 33 33 24 ... slowest runs (cycles): ... 33 33 33 33 33 33 33 33 33 564 min: 21 cycles q1: 24 cycles median: 30 cycles q3: 33 cycles max: 564 cycles RESULT TestSetjmpLongjmp_CycleCount: x86-64_nnacl_newlib_static= {30, 9} count Apparent clock speed: 2466 MHz TestClockGetTime: Measuring real time: 0.409 usec (4.0861e-07 sec) per iteration: 4.0861e-05 sec for 100 iterations 0.309 usec (3.08763e-07 sec) per iteration: 0.0755643 sec for 244732 iterations 0.311 usec (3.10818e-07 sec) per iteration: 0.0760671 sec for 244732 iterations 0.309 usec (3.08919e-07 sec) per iteration: 0.0756025 sec for 244732 iterations 0.325 usec (3.24788e-07 sec) per iteration: 0.0794861 sec for 244732 iterations 0.308 usec (3.08386e-07 sec) per iteration: 0.075472 sec for 244732 iterations mean: 0.312335 usec stddev: 0.006283 usec relative stddev: 2.01% RESULT TestClockGetTime: x86-64_nnacl_newlib_static= {0.312335, 0.006283} us Measuring clock cycles: first runs (cycles): 2538 864 840 849 960 891 846 843 846 846 ... slowest runs (cycles): ... 849 849 849 852 852 858 864 891 960 2538 min: 834 cycles q1: 840 cycles median: 846 cycles q3: 846 cycles max: 2538 cycles RESULT TestClockGetTime_CycleCount: x86-64_nnacl_newlib_static= {846, 6} count Apparent clock speed: 2709 MHz TestTlsVariable: Measuring real time: 0.011 usec (1.103e-08 sec) per iteration: 1.103e-06 sec for 100 iterations 0.006 usec (6.458e-09 sec) per iteration: 6.458e-06 sec for 1000 iterations 0.006 usec (6.042e-09 sec) per iteration: 6.042e-05 sec for 10000 iterations 0.007 usec (6.62322e-09 sec) per iteration: 0.10962 sec for 16550810 iterations 0.006 usec (6.49074e-09 sec) per iteration: 0.107427 sec for 16550810 iterations 0.007 usec (6.88435e-09 sec) per iteration: 0.113942 sec for 16550810 iterations 0.007 usec (6.65083e-09 sec) per iteration: 0.110077 sec for 16550810 iterations 0.006 usec (6.1832e-09 sec) per iteration: 0.102337 sec for 16550810 iterations mean: 0.006566 usec stddev: 0.000230 usec relative stddev: 3.50% RESULT TestTlsVariable: x86-64_nnacl_newlib_static= {0.006566, 0.000230} us Measuring clock cycles: first runs (cycles): 363 63 21 21 21 30 30 30 30 30 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 63 363 min: 21 cycles q1: 21 cycles median: 21 cycles q3: 30 cycles max: 363 cycles RESULT TestTlsVariable_CycleCount: x86-64_nnacl_newlib_static= {21, 9} count Apparent clock speed: 3198 MHz TestMmapAnonymous: Measuring real time: 10.443 usec (1.04435e-05 sec) per iteration: 0.00104435 sec for 100 iterations 9.618 usec (9.61762e-06 sec) per iteration: 0.0920887 sec for 9575 iterations 9.636 usec (9.63599e-06 sec) per iteration: 0.0922646 sec for 9575 iterations 9.641 usec (9.64116e-06 sec) per iteration: 0.0923141 sec for 9575 iterations 10.040 usec (1.00404e-05 sec) per iteration: 0.0961367 sec for 9575 iterations 9.649 usec (9.64881e-06 sec) per iteration: 0.0923873 sec for 9575 iterations mean: 9.716791 usec stddev: 0.162121 usec relative stddev: 1.67% RESULT TestMmapAnonymous: x86-64_nnacl_newlib_static= {9.716791, 0.162121} us Measuring clock cycles: first runs (cycles): 36627 27126 26295 26112 26010 26268 26361 26130 25848 25767 ... slowest runs (cycles): ... 26361 26367 26391 26397 26403 26487 26496 26520 27126 36627 min: 25743 cycles q1: 25917 cycles median: 26076 cycles q3: 26208 cycles max: 36627 cycles RESULT TestMmapAnonymous_CycleCount: x86-64_nnacl_newlib_static= {26076, 291} count Apparent clock speed: 2684 MHz TestAtomicIncrement: Measuring real time: 0.016 usec (1.621e-08 sec) per iteration: 1.621e-06 sec for 100 iterations 0.010 usec (1.0068e-08 sec) per iteration: 1.0068e-05 sec for 1000 iterations 0.010 usec (9.73296e-09 sec) per iteration: 0.0966722 sec for 9932459 iterations 0.010 usec (9.71205e-09 sec) per iteration: 0.0964645 sec for 9932459 iterations 0.010 usec (9.69772e-09 sec) per iteration: 0.0963222 sec for 9932459 iterations 0.010 usec (9.82626e-09 sec) per iteration: 0.0975989 sec for 9932459 iterations 0.010 usec (9.93476e-09 sec) per iteration: 0.0986766 sec for 9932459 iterations mean: 0.009781 usec stddev: 0.000089 usec relative stddev: 0.91% RESULT TestAtomicIncrement: x86-64_nnacl_newlib_static= {0.009781, 0.000089} us Measuring clock cycles: first runs (cycles): 210 51 48 48 51 48 51 48 51 48 ... slowest runs (cycles): ... 51 51 51 51 51 51 51 51 51 210 min: 39 cycles q1: 48 cycles median: 48 cycles q3: 51 cycles max: 210 cycles RESULT TestAtomicIncrement_CycleCount: x86-64_nnacl_newlib_static= {48, 3} count Apparent clock speed: 4908 MHz TestUncontendedMutexLock: Measuring real time: 0.030 usec (3.008e-08 sec) per iteration: 3.008e-06 sec for 100 iterations 0.023 usec (2.3418e-08 sec) per iteration: 2.3418e-05 sec for 1000 iterations 0.023 usec (2.31428e-08 sec) per iteration: 0.0988246 sec for 4270219 iterations 0.023 usec (2.30691e-08 sec) per iteration: 0.0985101 sec for 4270219 iterations 0.023 usec (2.31123e-08 sec) per iteration: 0.0986946 sec for 4270219 iterations 0.023 usec (2.34264e-08 sec) per iteration: 0.100036 sec for 4270219 iterations 0.023 usec (2.3205e-08 sec) per iteration: 0.0990904 sec for 4270219 iterations mean: 0.023191 usec stddev: 0.000126 usec relative stddev: 0.54% RESULT TestUncontendedMutexLock: x86-64_nnacl_newlib_static= {0.023191, 0.000126} us Measuring clock cycles: first runs (cycles): 447 111 78 90 87 90 87 90 87 90 ... slowest runs (cycles): ... 90 90 90 90 90 93 102 111 114 447 min: 78 cycles q1: 81 cycles median: 87 cycles q3: 90 cycles max: 447 cycles RESULT TestUncontendedMutexLock_CycleCount: x86-64_nnacl_newlib_static= {87, 9} count Apparent clock speed: 3751 MHz TestCondvarSignalNoOp: Measuring real time: 0.352 usec (3.5248e-07 sec) per iteration: 3.5248e-05 sec for 100 iterations 0.247 usec (2.47348e-07 sec) per iteration: 0.0701736 sec for 283704 iterations 0.244 usec (2.44228e-07 sec) per iteration: 0.0692885 sec for 283704 iterations 0.273 usec (2.72676e-07 sec) per iteration: 0.0773593 sec for 283704 iterations 0.280 usec (2.79727e-07 sec) per iteration: 0.0793597 sec for 283704 iterations 0.244 usec (2.43997e-07 sec) per iteration: 0.069223 sec for 283704 iterations mean: 0.257595 usec stddev: 0.015400 usec relative stddev: 5.98% RESULT TestCondvarSignalNoOp: x86-64_nnacl_newlib_static= {0.257595, 0.015400} us Measuring clock cycles: first runs (cycles): 1815 708 723 720 666 681 720 657 654 672 ... slowest runs (cycles): ... 681 684 708 720 720 720 723 723 726 1815 min: 648 cycles q1: 654 cycles median: 657 cycles q3: 663 cycles max: 1815 cycles RESULT TestCondvarSignalNoOp_CycleCount: x86-64_nnacl_newlib_static= {657, 9} count Apparent clock speed: 2551 MHz TestThreadCreateAndJoin: Measuring real time: 92.492 usec (9.24918e-05 sec) per iteration: 0.00924918 sec for 100 iterations 94.510 usec (9.45099e-05 sec) per iteration: 0.102165 sec for 1081 iterations 93.024 usec (9.30236e-05 sec) per iteration: 0.100558 sec for 1081 iterations 94.439 usec (9.44388e-05 sec) per iteration: 0.102088 sec for 1081 iterations 92.691 usec (9.26907e-05 sec) per iteration: 0.100199 sec for 1081 iterations 94.818 usec (9.4818e-05 sec) per iteration: 0.102498 sec for 1081 iterations mean: 93.896211 usec stddev: 0.864340 usec relative stddev: 0.92% RESULT TestThreadCreateAndJoin: x86-64_nnacl_newlib_static= {93.896211, 0.864340} us Measuring clock cycles: first runs (cycles): 268356 296586 262467 334899 246468 251586 245439 243114 243255 244371 ... slowest runs (cycles): ... 258825 259965 262101 262467 266922 268356 291618 294234 296586 334899 min: 228480 cycles q1: 243255 cycles median: 246366 cycles q3: 250797 cycles max: 334899 cycles RESULT TestThreadCreateAndJoin_CycleCount: x86-64_nnacl_newlib_static= {246366, 7542} count Apparent clock speed: 2624 MHz TestThreadWakeup: Measuring real time: 32.933 usec (3.29329e-05 sec) per iteration: 0.00329329 sec for 100 iterations 33.193 usec (3.31934e-05 sec) per iteration: 0.100775 sec for 3036 iterations 34.571 usec (3.45713e-05 sec) per iteration: 0.104958 sec for 3036 iterations 33.732 usec (3.37322e-05 sec) per iteration: 0.102411 sec for 3036 iterations 33.837 usec (3.38368e-05 sec) per iteration: 0.102729 sec for 3036 iterations 34.163 usec (3.41634e-05 sec) per iteration: 0.10372 sec for 3036 iterations mean: 33.899410 usec stddev: 0.458554 usec relative stddev: 1.35% RESULT TestThreadWakeup: x86-64_nnacl_newlib_static= {33.899410, 0.458554} us Measuring clock cycles: first runs (cycles): 127128 88827 111954 129897 99600 112206 320682 70887 96396 90537 ... slowest runs (cycles): ... 96504 99129 99600 103065 108264 111954 112206 127128 129897 320682 min: 70887 cycles q1: 91434 cycles median: 92418 cycles q3: 93270 cycles max: 320682 cycles RESULT TestThreadWakeup_CycleCount: x86-64_nnacl_newlib_static= {92418, 1836} count Apparent clock speed: 2726 MHz TestCatchingFault: Measuring real time: 33.811 usec (3.38109e-05 sec) per iteration: 0.00338109 sec for 100 iterations 34.894 usec (3.48939e-05 sec) per iteration: 0.103181 sec for 2957 iterations 33.486 usec (3.34864e-05 sec) per iteration: 0.0990192 sec for 2957 iterations 34.611 usec (3.46112e-05 sec) per iteration: 0.102345 sec for 2957 iterations 33.552 usec (3.3552e-05 sec) per iteration: 0.0992131 sec for 2957 iterations 34.061 usec (3.40606e-05 sec) per iteration: 0.100717 sec for 2957 iterations mean: 34.120777 usec stddev: 0.559966 usec relative stddev: 1.64% RESULT TestCatchingFault: x86-64_nnacl_newlib_static= {34.120777, 0.559966} us Measuring clock cycles: first runs (cycles): 109845 89586 96735 152859 142824 125523 112890 78606 134754 96075 ... slowest runs (cycles): ... 120231 120255 125523 126039 130755 134193 134754 139266 142824 152859 min: 66216 cycles q1: 68196 cycles median: 95139 cycles q3: 96825 cycles max: 152859 cycles RESULT TestCatchingFault_CycleCount: x86-64_nnacl_newlib_static= {95139, 28629} count Apparent clock speed: 2788 MHz TestThreadCreateAndJoinAfterSettingFaultHandler: Measuring real time: 92.874 usec (9.28744e-05 sec) per iteration: 0.00928744 sec for 100 iterations 93.575 usec (9.3575e-05 sec) per iteration: 0.100687 sec for 1076 iterations 93.400 usec (9.33997e-05 sec) per iteration: 0.100498 sec for 1076 iterations 93.570 usec (9.35704e-05 sec) per iteration: 0.100682 sec for 1076 iterations 92.504 usec (9.25044e-05 sec) per iteration: 0.0995348 sec for 1076 iterations 93.883 usec (9.38833e-05 sec) per iteration: 0.101018 sec for 1076 iterations mean: 93.386583 usec stddev: 0.467841 usec relative stddev: 0.50% RESULT TestThreadCreateAndJoinAfterSettingFaultHandler: x86-64_nnacl_newlib_static= {93.386583, 0.467841} us Measuring clock cycles: first runs (cycles): 235086 277794 319515 281712 302949 287424 303846 257820 260226 265770 ... slowest runs (cycles): ... 275709 277794 281712 283971 287424 295725 300516 302949 303846 319515 min: 232623 cycles q1: 251085 cycles median: 257604 cycles q3: 265710 cycles max: 319515 cycles RESULT TestThreadCreateAndJoinAfterSettingFaultHandler_CycleCount: x86-64_nnacl_newlib_static= {257604, 14625} count Apparent clock speed: 2758 MHz [ OK ] nacl_newlib.run_performance_test (6740 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 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 (9320 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 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 (1760 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 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.050 usec (5e-08 sec) per iteration: 5e-06 sec for 100 iterations 0.003 usec (3e-09 sec) per iteration: 3e-06 sec for 1000 iterations 0.003 usec (2.7e-09 sec) per iteration: 2.7e-05 sec for 10000 iterations 0.003 usec (2.74606e-09 sec) per iteration: 0.101706 sec for 37037037 iterations 0.003 usec (2.77312e-09 sec) per iteration: 0.102708 sec for 37037037 iterations 0.003 usec (2.6554e-09 sec) per iteration: 0.098348 sec for 37037037 iterations 0.003 usec (2.7641e-09 sec) per iteration: 0.102374 sec for 37037037 iterations 0.003 usec (3.06069e-09 sec) per iteration: 0.113359 sec for 37037037 iterations mean: 0.002800 usec stddev: 0.000137 usec relative stddev: 4.89% RESULT TestNull: trusted_mac_x86-64= {0.002800, 0.000137} us Measuring clock cycles: first runs (cycles): 312 21 30 33 30 30 30 30 30 30 ... slowest runs (cycles): ... 33 33 33 33 33 33 33 36 39 312 min: 18 cycles q1: 21 cycles median: 30 cycles q3: 30 cycles max: 312 cycles RESULT TestNull_CycleCount: trusted_mac_x86-64= {30, 9} count Apparent clock speed: 10715 MHz TestHostSyscall: Measuring real time: 1.220 usec (1.22e-06 sec) per iteration: 0.000122 sec for 100 iterations 1.028 usec (1.02799e-06 sec) per iteration: 0.084261 sec for 81967 iterations 1.038 usec (1.03821e-06 sec) per iteration: 0.085099 sec for 81967 iterations 1.043 usec (1.04321e-06 sec) per iteration: 0.085509 sec for 81967 iterations 1.041 usec (1.04097e-06 sec) per iteration: 0.085325 sec for 81967 iterations 1.052 usec (1.05201e-06 sec) per iteration: 0.08623 sec for 81967 iterations mean: 1.040477 usec stddev: 0.007770 usec relative stddev: 0.75% RESULT TestHostSyscall: trusted_mac_x86-64= {1.040477, 0.007770} us Measuring clock cycles: first runs (cycles): 3204 2835 2799 2799 2799 2790 2799 2799 2799 2799 ... slowest runs (cycles): ... 2832 2832 2832 2832 2832 2832 2832 2832 2835 3204 min: 2790 cycles q1: 2799 cycles median: 2799 cycles q3: 2823 cycles max: 3204 cycles RESULT TestHostSyscall_CycleCount: trusted_mac_x86-64= {2799, 24} count Apparent clock speed: 2690 MHz TestSetjmpLongjmp: Measuring real time: 5.160 usec (5.16e-06 sec) per iteration: 0.000516 sec for 100 iterations 4.681 usec (4.68089e-06 sec) per iteration: 0.090711 sec for 19379 iterations 4.682 usec (4.68156e-06 sec) per iteration: 0.090724 sec for 19379 iterations 4.781 usec (4.78074e-06 sec) per iteration: 0.092646 sec for 19379 iterations 4.678 usec (4.67754e-06 sec) per iteration: 0.090646 sec for 19379 iterations 4.640 usec (4.63982e-06 sec) per iteration: 0.089915 sec for 19379 iterations mean: 4.692110 usec stddev: 0.046989 usec relative stddev: 1.00% RESULT TestSetjmpLongjmp: trusted_mac_x86-64= {4.692110, 0.046989} us Measuring clock cycles: first runs (cycles): 13992 12354 12327 12327 12324 12321 12324 12324 12324 12333 ... slowest runs (cycles): ... 12360 12360 12363 12363 12363 12420 12420 12423 12513 13992 min: 12318 cycles q1: 12324 cycles median: 12333 cycles q3: 12354 cycles max: 13992 cycles RESULT TestSetjmpLongjmp_CycleCount: trusted_mac_x86-64= {12333, 30} count Apparent clock speed: 2628 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.76268e-08 sec) per iteration: 0.100814 sec for 1298701 iterations 0.078 usec (7.76453e-08 sec) per iteration: 0.100838 sec for 1298701 iterations 0.078 usec (7.75637e-08 sec) per iteration: 0.100732 sec for 1298701 iterations 0.078 usec (7.75806e-08 sec) per iteration: 0.100754 sec for 1298701 iterations 0.078 usec (7.76368e-08 sec) per iteration: 0.100827 sec for 1298701 iterations mean: 0.077611 usec stddev: 0.000032 usec relative stddev: 0.04% RESULT TestClockGetTime: trusted_mac_x86-64= {0.077611, 0.000032} us Measuring clock cycles: first runs (cycles): 1299 228 219 219 219 219 219 216 216 216 ... slowest runs (cycles): ... 219 219 219 219 228 228 228 228 252 1299 min: 216 cycles q1: 216 cycles median: 216 cycles q3: 219 cycles max: 1299 cycles RESULT TestClockGetTime_CycleCount: trusted_mac_x86-64= {216, 3} count Apparent clock speed: 2783 MHz TestMmapAnonymous: Measuring real time: 3.400 usec (3.4e-06 sec) per iteration: 0.00034 sec for 100 iterations 3.007 usec (3.00745e-06 sec) per iteration: 0.088452 sec for 29411 iterations 2.979 usec (2.97875e-06 sec) per iteration: 0.087608 sec for 29411 iterations 3.148 usec (3.14801e-06 sec) per iteration: 0.092586 sec for 29411 iterations 3.015 usec (3.01479e-06 sec) per iteration: 0.088668 sec for 29411 iterations 3.056 usec (3.05641e-06 sec) per iteration: 0.089892 sec for 29411 iterations mean: 3.041080 usec stddev: 0.058950 usec relative stddev: 1.94% RESULT TestMmapAnonymous: trusted_mac_x86-64= {3.041080, 0.058950} us Measuring clock cycles: first runs (cycles): 11415 8331 8049 7863 7887 7887 7881 7884 7896 8058 ... slowest runs (cycles): ... 8007 8010 8019 8019 8049 8058 8331 8703 11415 24459 min: 7845 cycles q1: 7878 cycles median: 7893 cycles q3: 7923 cycles max: 24459 cycles RESULT TestMmapAnonymous_CycleCount: trusted_mac_x86-64= {7893, 45} count Apparent clock speed: 2595 MHz TestAtomicIncrement: Measuring real time: 0.010 usec (1e-08 sec) per iteration: 1e-06 sec for 100 iterations 0.011 usec (1.1e-08 sec) per iteration: 1.1e-05 sec for 1000 iterations 0.010 usec (9.69617e-09 sec) per iteration: 0.088147 sec for 9090909 iterations 0.010 usec (9.67802e-09 sec) per iteration: 0.087982 sec for 9090909 iterations 0.010 usec (9.71377e-09 sec) per iteration: 0.088307 sec for 9090909 iterations 0.010 usec (9.67417e-09 sec) per iteration: 0.087947 sec for 9090909 iterations 0.010 usec (9.70156e-09 sec) per iteration: 0.088196 sec for 9090909 iterations mean: 0.009693 usec stddev: 0.000015 usec relative stddev: 0.15% RESULT TestAtomicIncrement: trusted_mac_x86-64= {0.009693, 0.000015} us Measuring clock cycles: first runs (cycles): 399 60 60 54 54 54 54 54 54 57 ... slowest runs (cycles): ... 57 57 57 60 60 60 60 66 72 399 min: 54 cycles q1: 54 cycles median: 54 cycles q3: 54 cycles max: 399 cycles RESULT TestAtomicIncrement_CycleCount: trusted_mac_x86-64= {54, 0} count Apparent clock speed: 5571 MHz TestUncontendedMutexLock: Measuring real time: 0.220 usec (2.2e-07 sec) per iteration: 2.2e-05 sec for 100 iterations 0.026 usec (2.6367e-08 sec) per iteration: 0.011985 sec for 454545 iterations 0.026 usec (2.63714e-08 sec) per iteration: 0.011987 sec for 454545 iterations 0.026 usec (2.63846e-08 sec) per iteration: 0.011993 sec for 454545 iterations 0.026 usec (2.63868e-08 sec) per iteration: 0.011994 sec for 454545 iterations 0.026 usec (2.6356e-08 sec) per iteration: 0.01198 sec for 454545 iterations mean: 0.026373 usec stddev: 0.000011 usec relative stddev: 0.04% RESULT TestUncontendedMutexLock: trusted_mac_x86-64= {0.026373, 0.000011} us Measuring clock cycles: first runs (cycles): 495 105 93 102 105 93 102 102 96 102 ... slowest runs (cycles): ... 105 105 105 105 105 105 105 105 111 495 min: 93 cycles q1: 102 cycles median: 102 cycles q3: 102 cycles max: 495 cycles RESULT TestUncontendedMutexLock_CycleCount: trusted_mac_x86-64= {102, 0} count Apparent clock speed: 3868 MHz TestCondvarSignalNoOp: Measuring real time: 0.110 usec (1.1e-07 sec) per iteration: 1.1e-05 sec for 100 iterations 0.015 usec (1.50172e-08 sec) per iteration: 0.013652 sec for 909090 iterations 0.015 usec (1.50491e-08 sec) per iteration: 0.013681 sec for 909090 iterations 0.015 usec (1.49325e-08 sec) per iteration: 0.013575 sec for 909090 iterations 0.015 usec (1.50436e-08 sec) per iteration: 0.013676 sec for 909090 iterations 0.015 usec (1.5103e-08 sec) per iteration: 0.01373 sec for 909090 iterations mean: 0.015029 usec stddev: 0.000056 usec relative stddev: 0.37% RESULT TestCondvarSignalNoOp: trusted_mac_x86-64= {0.015029, 0.000056} us Measuring clock cycles: first runs (cycles): 657 99 69 75 81 72 69 69 81 81 ... slowest runs (cycles): ... 81 81 81 81 81 81 81 81 99 657 min: 66 cycles q1: 69 cycles median: 72 cycles q3: 78 cycles max: 657 cycles RESULT TestCondvarSignalNoOp_CycleCount: trusted_mac_x86-64= {72, 9} count Apparent clock speed: 4791 MHz TestThreadCreateAndJoin: Measuring real time: 82.870 usec (8.287e-05 sec) per iteration: 0.008287 sec for 100 iterations 83.769 usec (8.37695e-05 sec) per iteration: 0.101026 sec for 1206 iterations 82.056 usec (8.20564e-05 sec) per iteration: 0.09896 sec for 1206 iterations 81.879 usec (8.18789e-05 sec) per iteration: 0.098746 sec for 1206 iterations 84.612 usec (8.46119e-05 sec) per iteration: 0.102042 sec for 1206 iterations 80.694 usec (8.0694e-05 sec) per iteration: 0.097317 sec for 1206 iterations mean: 82.602156 usec stddev: 1.404546 usec relative stddev: 1.70% RESULT TestThreadCreateAndJoin: trusted_mac_x86-64= {82.602156, 1.404546} us Measuring clock cycles: first runs (cycles): 247188 210579 176049 150111 165375 221328 147114 250140 234270 229668 ... slowest runs (cycles): ... 247158 247188 248115 248835 250140 251004 251100 252120 254748 266547 min: 139074 cycles q1: 227700 cycles median: 231279 cycles q3: 241338 cycles max: 266547 cycles RESULT TestThreadCreateAndJoin_CycleCount: trusted_mac_x86-64= {231279, 13638} count Apparent clock speed: 2800 MHz TestThreadWakeup: Measuring real time: 20.580 usec (2.058e-05 sec) per iteration: 0.002058 sec for 100 iterations 19.608 usec (1.96077e-05 sec) per iteration: 0.095274 sec for 4859 iterations 19.693 usec (1.96931e-05 sec) per iteration: 0.095689 sec for 4859 iterations 19.523 usec (1.95234e-05 sec) per iteration: 0.094864 sec for 4859 iterations 19.465 usec (1.94653e-05 sec) per iteration: 0.094582 sec for 4859 iterations 19.528 usec (1.95281e-05 sec) per iteration: 0.094887 sec for 4859 iterations mean: 19.563532 usec stddev: 0.079081 usec relative stddev: 0.40% RESULT TestThreadWakeup: trusted_mac_x86-64= {19.563532, 0.079081} us Measuring clock cycles: first runs (cycles): 63279 52086 50949 51081 50763 50220 62121 51222 62811 52686 ... slowest runs (cycles): ... 63618 63987 65535 65631 71349 71421 82380 82587 109935 147963 min: 50220 cycles q1: 50967 cycles median: 51825 cycles q3: 57342 cycles max: 147963 cycles RESULT TestThreadWakeup_CycleCount: trusted_mac_x86-64= {51825, 6375} count Apparent clock speed: 2649 MHz WARNING: should have taken less than 2.000000 secs [ OK ] nacl_newlib.run_trusted_performance_test (3990 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