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 scons: Reading SConscript files ... ====================================================================== SCONS ARGS:['scons.py', '--verbose', '-k', '-j1', '--mode=nacl,opt-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 = 1550153228, usec = 409216 } Thu Feb 14 06:07:08 2019 ====================================================================== The following environments have been configured ====================================================================== NACL_BUILD_FAMILY: UNTRUSTED BUILD_TYPE: nacl TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/obj BUILD_TYPE_DESCRIPTION: NaCl module build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang ASPPCOM: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_GNU_SOURCE=1 -D_POSIX_C_SOURCE=199506 -D_XOPEN_SOURCE=600 -DDYNAMIC_ANNOTATIONS_ENABLED=1 -DDYNAMIC_ANNOTATIONS_PREFIX=NACL_ -DNACL_BUILD_ARCH=x86 -DNACL_BUILD_SUBARCH=64 -I/b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/include -I/b/s/w/ir/kitchen-workdir -c -o UNKNOWN COMPILER NACL_BUILD_FAMILY: TRUSTED BUILD_TYPE: opt-mac TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj BUILD_TYPE_DESCRIPTION: MacOS opt build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/third_party/llvm-build/Release+Asserts/bin/clang ASPPCOM: /b/s/w/ir/kitchen-workdir/third_party/llvm-build/Release+Asserts/bin/clang -isysroot /b/s/w/ir/cache/osx_sdk/XCode.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX10.13.sdk -mmacosx-version-min=10.6 -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -DNDEBUG -I/b/s/w/ir/kitchen-workdir -c -o UNKNOWN COMPILER NACL_BUILD_FAMILY: UNTRUSTED_IRT BUILD_TYPE: nacl_irt TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64/obj BUILD_TYPE_DESCRIPTION: NaCl IRT build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang ASPPCOM: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_GNU_SOURCE=1 -D_POSIX_C_SOURCE=199506 -D_XOPEN_SOURCE=600 -DDYNAMIC_ANNOTATIONS_ENABLED=1 -DDYNAMIC_ANNOTATIONS_PREFIX=NACL_ -DNACL_BUILD_ARCH=x86 -DNACL_BUILD_SUBARCH=64 -I/b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64/include -I/b/s/w/ir/kitchen-workdir -I/b/s/w/ir/kitchen-workdir/native_client/src/untrusted/pthread -c -o UNKNOWN COMPILER *** BROKEN run_ncval_annotate_test *** BROKEN run_gdb_invalid_memory_test *** BROKEN run_nanosleep_test *** BROKEN run_timefuncs_test *** BROKEN run_raw_timefuncs_test *** BROKEN run_main_thread_pthread_exit_test2 *** BROKEN run_overflowinline_test *** BROKEN run_stack_frame_noopt_frame_test *** BROKEN run_stack_frame_noopt_noframe_test *** BROKEN run_stack_frame_opt_frame_test *** BROKEN run_stack_frame_opt_noframe_test *** BROKEN run_vla_test *** BROKEN run_nacl_sync_cond_test SKIPPING test text_overlaps_rodata SKIPPING test text_overlaps_data There are 13 broken tests. ====================================================================== B U I L D - O U T P U T: ====================================================================== scons: done reading SConscript files. scons: Building targets ... /b/s/w/ir/cache/vpython/7c7ecd/bin/python tools/command_tester.py --name nacl_newlib.run_benchmark_test --time_warning 10 --time_error 100 --perf_env_description 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/opt-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/opt-mac-x86-64/staging/sel_ldr -- scons-out/nacl-x86-64/obj/tests/benchmark/benchmark_test.nexe x86-64_nnacl_newlib_static [39608,2635494272:15:25:23.175802] Native Client module will be loaded at base address 0x000028e300000000 Running suite of 1 benchmarks: Running Benchmark: Life (SIMD version)... RESULT BenchmarkLife: x86-64_nnacl_newlib_static= {0.067190, 0.001100} seconds --------------------------------------------------------------- Done running benchmark suite. [ OK ] nacl_newlib.run_benchmark_test (860 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python tools/command_tester.py --name nacl_newlib.run_clock_cputime_test --time_warning 60 --time_error 600 --perf_env_description 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/opt-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/opt-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 (66210 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= 525.260 KB RESULT hello_world_size.out: ZIPPED_x86-64_nnacl_newlib_static= 187.859 KB /b/s/w/ir/cache/vpython/7c7ecd/bin/python tools/command_tester.py --name nacl_newlib.run_performance_test --time_warning 10 --time_error 100 --perf_env_description 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/opt-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/opt-mac-x86-64/staging/sel_ldr -e -- scons-out/nacl-x86-64/obj/tests/performance/performance_test.nexe x86-64_nnacl_newlib_static [39616,2635494272:15:25:37.320504] Native Client module will be loaded at base address 0x0000037f00000000 TestNull: Measuring real time: 0.007 usec (7.02e-09 sec) per iteration: 7.02e-07 sec for 100 iterations 0.002 usec (2.279e-09 sec) per iteration: 2.279e-06 sec for 1000 iterations 0.002 usec (2.0275e-09 sec) per iteration: 2.0275e-05 sec for 10000 iterations 0.002 usec (2.02651e-09 sec) per iteration: 0.0999513 sec for 49321824 iterations 0.002 usec (2.0434e-09 sec) per iteration: 0.100784 sec for 49321824 iterations 0.002 usec (2.07352e-09 sec) per iteration: 0.10227 sec for 49321824 iterations 0.002 usec (2.08666e-09 sec) per iteration: 0.102918 sec for 49321824 iterations 0.002 usec (2.07197e-09 sec) per iteration: 0.102193 sec for 49321824 iterations mean: 0.002060 usec stddev: 0.000022 usec relative stddev: 1.07% RESULT TestNull: x86-64_nnacl_newlib_static= {0.002060, 0.000022} us Measuring clock cycles: first runs (cycles): 234 21 30 30 27 30 18 21 18 21 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 30 234 min: 18 cycles q1: 18 cycles median: 21 cycles q3: 27 cycles max: 234 cycles RESULT TestNull_CycleCount: x86-64_nnacl_newlib_static= {21, 9} count Apparent clock speed: 10192 MHz TestNaClSyscall: Measuring real time: 0.158 usec (1.576e-07 sec) per iteration: 1.576e-05 sec for 100 iterations 0.158 usec (1.58336e-07 sec) per iteration: 0.100467 sec for 634517 iterations 0.158 usec (1.58374e-07 sec) per iteration: 0.100491 sec for 634517 iterations 0.156 usec (1.5599e-07 sec) per iteration: 0.0989783 sec for 634517 iterations 0.157 usec (1.56932e-07 sec) per iteration: 0.0995758 sec for 634517 iterations 0.163 usec (1.62592e-07 sec) per iteration: 0.103168 sec for 634517 iterations mean: 0.158445 usec stddev: 0.002260 usec relative stddev: 1.43% RESULT TestNaClSyscall: x86-64_nnacl_newlib_static= {0.158445, 0.002260} us Measuring clock cycles: first runs (cycles): 705 300 291 291 291 288 297 300 300 300 ... slowest runs (cycles): ... 300 300 300 300 300 303 303 306 306 705 min: 288 cycles q1: 291 cycles median: 291 cycles q3: 300 cycles max: 705 cycles RESULT TestNaClSyscall_CycleCount: x86-64_nnacl_newlib_static= {291, 9} count Apparent clock speed: 1837 MHz TestSetjmpLongjmp: Measuring real time: 0.017 usec (1.682e-08 sec) per iteration: 1.682e-06 sec for 100 iterations 0.012 usec (1.239e-08 sec) per iteration: 1.239e-05 sec for 1000 iterations 0.012 usec (1.20874e-08 sec) per iteration: 0.0975576 sec for 8071025 iterations 0.012 usec (1.19231e-08 sec) per iteration: 0.0962314 sec for 8071025 iterations 0.012 usec (1.20407e-08 sec) per iteration: 0.0971806 sec for 8071025 iterations 0.012 usec (1.2404e-08 sec) per iteration: 0.100113 sec for 8071025 iterations 0.012 usec (1.20595e-08 sec) per iteration: 0.0973328 sec for 8071025 iterations mean: 0.012103 usec stddev: 0.000161 usec relative stddev: 1.33% RESULT TestSetjmpLongjmp: x86-64_nnacl_newlib_static= {0.012103, 0.000161} us Measuring clock cycles: first runs (cycles): 480 24 24 33 36 33 33 24 24 24 ... slowest runs (cycles): ... 33 33 33 33 33 33 33 33 36 480 min: 21 cycles q1: 24 cycles median: 30 cycles q3: 33 cycles max: 480 cycles RESULT TestSetjmpLongjmp_CycleCount: x86-64_nnacl_newlib_static= {30, 9} count Apparent clock speed: 2479 MHz TestClockGetTime: Measuring real time: 0.163 usec (1.6282e-07 sec) per iteration: 1.6282e-05 sec for 100 iterations 0.160 usec (1.60105e-07 sec) per iteration: 0.0983323 sec for 614175 iterations 0.161 usec (1.61213e-07 sec) per iteration: 0.0990128 sec for 614175 iterations 0.159 usec (1.58778e-07 sec) per iteration: 0.0975174 sec for 614175 iterations 0.158 usec (1.57971e-07 sec) per iteration: 0.0970218 sec for 614175 iterations 0.158 usec (1.58386e-07 sec) per iteration: 0.097277 sec for 614175 iterations mean: 0.159290 usec stddev: 0.001198 usec relative stddev: 0.75% RESULT TestClockGetTime: x86-64_nnacl_newlib_static= {0.159290, 0.001198} us Measuring clock cycles: first runs (cycles): 1560 516 453 438 435 435 435 429 441 429 ... slowest runs (cycles): ... 438 438 438 438 441 444 444 453 516 1560 min: 429 cycles q1: 435 cycles median: 435 cycles q3: 435 cycles max: 1560 cycles RESULT TestClockGetTime_CycleCount: x86-64_nnacl_newlib_static= {435, 0} count Apparent clock speed: 2731 MHz TestTlsVariable: Measuring real time: 0.010 usec (9.69e-09 sec) per iteration: 9.69e-07 sec for 100 iterations 0.006 usec (6.28e-09 sec) per iteration: 6.28e-06 sec for 1000 iterations 0.009 usec (9.2264e-09 sec) per iteration: 9.2264e-05 sec for 10000 iterations 0.006 usec (6.14663e-09 sec) per iteration: 0.06662 sec for 10838463 iterations 0.006 usec (6.04275e-09 sec) per iteration: 0.0654941 sec for 10838463 iterations 0.006 usec (6.0538e-09 sec) per iteration: 0.0656139 sec for 10838463 iterations 0.006 usec (6.11681e-09 sec) per iteration: 0.0662968 sec for 10838463 iterations 0.006 usec (6.05393e-09 sec) per iteration: 0.0656153 sec for 10838463 iterations mean: 0.006083 usec stddev: 0.000041 usec relative stddev: 0.68% RESULT TestTlsVariable: x86-64_nnacl_newlib_static= {0.006083, 0.000041} us Measuring clock cycles: first runs (cycles): 363 69 18 21 21 21 21 18 30 27 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 69 363 min: 18 cycles q1: 18 cycles median: 21 cycles q3: 30 cycles max: 363 cycles RESULT TestTlsVariable_CycleCount: x86-64_nnacl_newlib_static= {21, 12} count Apparent clock speed: 3452 MHz TestMmapAnonymous: Measuring real time: 9.036 usec (9.03583e-06 sec) per iteration: 0.000903583 sec for 100 iterations 8.593 usec (8.59339e-06 sec) per iteration: 0.0951031 sec for 11067 iterations 8.563 usec (8.56289e-06 sec) per iteration: 0.0947655 sec for 11067 iterations 8.634 usec (8.63351e-06 sec) per iteration: 0.0955471 sec for 11067 iterations 8.611 usec (8.61147e-06 sec) per iteration: 0.0953031 sec for 11067 iterations 8.510 usec (8.51012e-06 sec) per iteration: 0.0941815 sec for 11067 iterations mean: 8.582276 usec stddev: 0.042858 usec relative stddev: 0.50% RESULT TestMmapAnonymous: x86-64_nnacl_newlib_static= {8.582276, 0.042858} us Measuring clock cycles: first runs (cycles): 33039 24555 23874 23715 23430 23931 23520 23397 23457 23373 ... slowest runs (cycles): ... 23931 23934 23982 24465 24555 30135 33039 34053 36777 40179 min: 23271 cycles q1: 23388 cycles median: 23568 cycles q3: 23628 cycles max: 40179 cycles RESULT TestMmapAnonymous_CycleCount: x86-64_nnacl_newlib_static= {23568, 240} count Apparent clock speed: 2746 MHz TestAtomicIncrement: Measuring real time: 0.015 usec (1.493e-08 sec) per iteration: 1.493e-06 sec for 100 iterations 0.010 usec (9.907e-09 sec) per iteration: 9.907e-06 sec for 1000 iterations 0.010 usec (9.6905e-09 sec) per iteration: 9.6905e-05 sec for 10000 iterations 0.010 usec (9.87534e-09 sec) per iteration: 0.101907 sec for 10319384 iterations 0.010 usec (1.01465e-08 sec) per iteration: 0.104706 sec for 10319384 iterations 0.010 usec (9.58088e-09 sec) per iteration: 0.0988688 sec for 10319384 iterations 0.010 usec (9.71979e-09 sec) per iteration: 0.100302 sec for 10319384 iterations 0.010 usec (9.56784e-09 sec) per iteration: 0.0987342 sec for 10319384 iterations mean: 0.009778 usec stddev: 0.000215 usec relative stddev: 2.20% RESULT TestAtomicIncrement: x86-64_nnacl_newlib_static= {0.009778, 0.000215} us Measuring clock cycles: first runs (cycles): 234 54 57 42 54 42 39 57 39 42 ... slowest runs (cycles): ... 57 57 57 57 57 57 57 57 57 234 min: 39 cycles q1: 39 cycles median: 42 cycles q3: 54 cycles max: 234 cycles RESULT TestAtomicIncrement_CycleCount: x86-64_nnacl_newlib_static= {42, 15} count Apparent clock speed: 4295 MHz TestUncontendedMutexLock: Measuring real time: 0.027 usec (2.725e-08 sec) per iteration: 2.725e-06 sec for 100 iterations 0.023 usec (2.3255e-08 sec) per iteration: 2.3255e-05 sec for 1000 iterations 0.023 usec (2.29481e-08 sec) per iteration: 0.0986805 sec for 4300150 iterations 0.023 usec (2.29774e-08 sec) per iteration: 0.0988064 sec for 4300150 iterations 0.023 usec (2.31859e-08 sec) per iteration: 0.099703 sec for 4300150 iterations 0.023 usec (2.27252e-08 sec) per iteration: 0.0977218 sec for 4300150 iterations 0.023 usec (2.34464e-08 sec) per iteration: 0.100823 sec for 4300150 iterations mean: 0.023057 usec stddev: 0.000244 usec relative stddev: 1.06% RESULT TestUncontendedMutexLock: x86-64_nnacl_newlib_static= {0.023057, 0.000244} us Measuring clock cycles: first runs (cycles): 513 111 81 81 81 81 90 90 90 90 ... slowest runs (cycles): ... 90 90 90 90 90 90 90 93 111 513 min: 81 cycles q1: 81 cycles median: 90 cycles q3: 90 cycles max: 513 cycles RESULT TestUncontendedMutexLock_CycleCount: x86-64_nnacl_newlib_static= {90, 9} count Apparent clock speed: 3903 MHz TestCondvarSignalNoOp: Measuring real time: 0.256 usec (2.5619e-07 sec) per iteration: 2.5619e-05 sec for 100 iterations 0.162 usec (1.61879e-07 sec) per iteration: 0.0631872 sec for 390335 iterations 0.168 usec (1.67701e-07 sec) per iteration: 0.0654594 sec for 390335 iterations 0.162 usec (1.62281e-07 sec) per iteration: 0.0633438 sec for 390335 iterations 0.159 usec (1.58818e-07 sec) per iteration: 0.0619921 sec for 390335 iterations 0.165 usec (1.65207e-07 sec) per iteration: 0.064486 sec for 390335 iterations mean: 0.163177 usec stddev: 0.003036 usec relative stddev: 1.86% RESULT TestCondvarSignalNoOp: x86-64_nnacl_newlib_static= {0.163177, 0.003036} us Measuring clock cycles: first runs (cycles): 1383 438 432 432 432 432 432 435 432 432 ... slowest runs (cycles): ... 432 432 432 432 432 435 435 435 438 1383 min: 420 cycles q1: 432 cycles median: 432 cycles q3: 432 cycles max: 1383 cycles RESULT TestCondvarSignalNoOp_CycleCount: x86-64_nnacl_newlib_static= {432, 0} count Apparent clock speed: 2647 MHz TestThreadCreateAndJoin: Measuring real time: 64.923 usec (6.49225e-05 sec) per iteration: 0.00649225 sec for 100 iterations 65.680 usec (6.56798e-05 sec) per iteration: 0.101147 sec for 1540 iterations 64.511 usec (6.45115e-05 sec) per iteration: 0.0993477 sec for 1540 iterations 63.373 usec (6.3373e-05 sec) per iteration: 0.0975945 sec for 1540 iterations 63.379 usec (6.33794e-05 sec) per iteration: 0.0976043 sec for 1540 iterations 63.592 usec (6.35916e-05 sec) per iteration: 0.0979311 sec for 1540 iterations mean: 64.107079 usec stddev: 0.891197 usec relative stddev: 1.39% RESULT TestThreadCreateAndJoin: x86-64_nnacl_newlib_static= {64.107079, 0.891197} us Measuring clock cycles: first runs (cycles): 170661 152016 198327 245658 212976 196911 165696 178176 173205 173232 ... slowest runs (cycles): ... 173388 175554 176553 178176 180738 185661 196911 198327 212976 245658 min: 152016 cycles q1: 169290 cycles median: 170391 cycles q3: 171765 cycles max: 245658 cycles RESULT TestThreadCreateAndJoin_CycleCount: x86-64_nnacl_newlib_static= {170391, 2475} count Apparent clock speed: 2658 MHz TestThreadWakeup: Measuring real time: 32.574 usec (3.25735e-05 sec) per iteration: 0.00325735 sec for 100 iterations 30.940 usec (3.09397e-05 sec) per iteration: 0.094954 sec for 3069 iterations 30.868 usec (3.08683e-05 sec) per iteration: 0.0947349 sec for 3069 iterations 30.833 usec (3.08334e-05 sec) per iteration: 0.0946278 sec for 3069 iterations 32.829 usec (3.28293e-05 sec) per iteration: 0.100753 sec for 3069 iterations 32.658 usec (3.26583e-05 sec) per iteration: 0.100228 sec for 3069 iterations mean: 31.625813 usec stddev: 0.915070 usec relative stddev: 2.89% RESULT TestThreadWakeup: x86-64_nnacl_newlib_static= {31.625813, 0.915070} us Measuring clock cycles: first runs (cycles): 106779 110946 95937 95418 97281 94548 110892 97824 91695 86286 ... slowest runs (cycles): ... 95937 97281 97824 106779 107541 110892 110946 111873 113427 124089 min: 77340 cycles q1: 82632 cycles median: 83754 cycles q3: 86688 cycles max: 124089 cycles RESULT TestThreadWakeup_CycleCount: x86-64_nnacl_newlib_static= {83754, 4056} count Apparent clock speed: 2648 MHz TestCatchingFault: Measuring real time: 32.031 usec (3.20311e-05 sec) per iteration: 0.0032031 sec for 100 iterations 30.880 usec (3.08799e-05 sec) per iteration: 0.0963763 sec for 3121 iterations 30.992 usec (3.0992e-05 sec) per iteration: 0.0967261 sec for 3121 iterations 30.858 usec (3.08584e-05 sec) per iteration: 0.0963092 sec for 3121 iterations 30.997 usec (3.09967e-05 sec) per iteration: 0.0967406 sec for 3121 iterations 30.960 usec (3.09605e-05 sec) per iteration: 0.0966276 sec for 3121 iterations mean: 30.937506 usec stddev: 0.057557 usec relative stddev: 0.19% RESULT TestCatchingFault: x86-64_nnacl_newlib_static= {30.937506, 0.057557} us Measuring clock cycles: first runs (cycles): 114303 93450 96930 99168 125073 125154 98640 173925 134040 103596 ... slowest runs (cycles): ... 101547 101793 103596 110238 114303 118092 125073 125154 134040 173925 min: 80358 cycles q1: 81768 cycles median: 82446 cycles q3: 84282 cycles max: 173925 cycles RESULT TestCatchingFault_CycleCount: x86-64_nnacl_newlib_static= {82446, 2514} count Apparent clock speed: 2665 MHz TestThreadCreateAndJoinAfterSettingFaultHandler: Measuring real time: 65.017 usec (6.50168e-05 sec) per iteration: 0.00650168 sec for 100 iterations 63.005 usec (6.30054e-05 sec) per iteration: 0.0969022 sec for 1538 iterations 63.500 usec (6.35001e-05 sec) per iteration: 0.0976631 sec for 1538 iterations 63.020 usec (6.30199e-05 sec) per iteration: 0.0969246 sec for 1538 iterations 63.760 usec (6.376e-05 sec) per iteration: 0.0980628 sec for 1538 iterations 63.573 usec (6.35727e-05 sec) per iteration: 0.0977749 sec for 1538 iterations mean: 63.371607 usec stddev: 0.305155 usec relative stddev: 0.48% RESULT TestThreadCreateAndJoinAfterSettingFaultHandler: x86-64_nnacl_newlib_static= {63.371607, 0.305155} us Measuring clock cycles: first runs (cycles): 175731 168591 180393 418566 212502 194766 194463 189612 174282 175086 ... slowest runs (cycles): ... 182622 185952 186054 189612 194463 194766 208371 212502 222849 418566 min: 154050 cycles q1: 156393 cycles median: 166239 cycles q3: 169854 cycles max: 418566 cycles RESULT TestThreadCreateAndJoinAfterSettingFaultHandler_CycleCount: x86-64_nnacl_newlib_static= {166239, 13461} count Apparent clock speed: 2623 MHz [ OK ] nacl_newlib.run_performance_test (6450 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/opt-mac-x86-64/test_results/nacl_clock_cputime_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/src/shared/platform/nacl_clock_test -c [ RUN ] nacl_newlib.run_nacl_clock_cputime_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/src/shared/platform/nacl_clock_test -c [ OK ] nacl_newlib.run_nacl_clock_cputime_test (1510 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python /b/s/w/ir/kitchen-workdir/native_client/tools/command_tester.py --name nacl_newlib.run_nacl_interval_multi_reg_test --time_warning 60 --time_error 600 --perf_env_description trusted_mac_x86-64 --subarch 64 --arch x86 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/test_results/nacl_interval_multi_reg_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/src/trusted/interval_multiset/nacl_interval_test -k NaClIntervalListMultiset -k NaClIntervalRangeTree -c 1000000 [ RUN ] nacl_newlib.run_nacl_interval_multi_reg_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/src/trusted/interval_multiset/nacl_interval_test -k NaClIntervalListMultiset -k NaClIntervalRangeTree -c 1000000 [ OK ] nacl_newlib.run_nacl_interval_multi_reg_test (730 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/opt-mac-x86-64/test_results/performance_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/tests/performance/performance_test trusted_mac_x86-64 [ RUN ] nacl_newlib.run_trusted_performance_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/tests/performance/performance_test trusted_mac_x86-64 TestNull: Measuring real time: 0.010 usec (1e-08 sec) per iteration: 1e-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.68013e-09 sec) per iteration: 0.099264 sec for 37037037 iterations 0.003 usec (2.68504e-09 sec) per iteration: 0.099446 sec for 37037037 iterations 0.003 usec (2.67727e-09 sec) per iteration: 0.099158 sec for 37037037 iterations 0.003 usec (2.66922e-09 sec) per iteration: 0.09886 sec for 37037037 iterations 0.003 usec (2.66863e-09 sec) per iteration: 0.098838 sec for 37037037 iterations mean: 0.002676 usec stddev: 0.000006 usec relative stddev: 0.24% RESULT TestNull: trusted_mac_x86-64= {0.002676, 0.000006} us Measuring clock cycles: first runs (cycles): 204 36 18 21 18 21 18 21 33 21 ... slowest runs (cycles): ... 36 36 36 36 36 36 36 36 36 204 min: 18 cycles q1: 21 cycles median: 21 cycles q3: 21 cycles max: 204 cycles RESULT TestNull_CycleCount: trusted_mac_x86-64= {21, 0} count Apparent clock speed: 7847 MHz TestHostSyscall: Measuring real time: 1.260 usec (1.26e-06 sec) per iteration: 0.000126 sec for 100 iterations 0.978 usec (9.77774e-07 sec) per iteration: 0.077601 sec for 79365 iterations 0.964 usec (9.63649e-07 sec) per iteration: 0.07648 sec for 79365 iterations 0.972 usec (9.72368e-07 sec) per iteration: 0.077172 sec for 79365 iterations 0.959 usec (9.59327e-07 sec) per iteration: 0.076137 sec for 79365 iterations 1.001 usec (1.0011e-06 sec) per iteration: 0.079452 sec for 79365 iterations mean: 0.974843 usec stddev: 0.014629 usec relative stddev: 1.50% RESULT TestHostSyscall: trusted_mac_x86-64= {0.974843, 0.014629} us Measuring clock cycles: first runs (cycles): 3186 2793 2751 2754 2748 2754 2751 2754 2751 2754 ... slowest runs (cycles): ... 2772 2775 2775 2775 2775 2775 2775 2775 2793 3186 min: 2742 cycles q1: 2751 cycles median: 2763 cycles q3: 2766 cycles max: 3186 cycles RESULT TestHostSyscall_CycleCount: trusted_mac_x86-64= {2763, 15} count Apparent clock speed: 2834 MHz TestSetjmpLongjmp: Measuring real time: 5.370 usec (5.37e-06 sec) per iteration: 0.000537 sec for 100 iterations 4.947 usec (4.94673e-06 sec) per iteration: 0.092113 sec for 18621 iterations 4.949 usec (4.94936e-06 sec) per iteration: 0.092162 sec for 18621 iterations 4.819 usec (4.81897e-06 sec) per iteration: 0.089734 sec for 18621 iterations 4.934 usec (4.93373e-06 sec) per iteration: 0.091871 sec for 18621 iterations 4.939 usec (4.93862e-06 sec) per iteration: 0.091962 sec for 18621 iterations mean: 4.917480 usec stddev: 0.049572 usec relative stddev: 1.01% RESULT TestSetjmpLongjmp: trusted_mac_x86-64= {4.917480, 0.049572} us Measuring clock cycles: first runs (cycles): 13821 12753 12747 12738 12750 12729 12747 12759 12750 12750 ... slowest runs (cycles): ... 12798 12798 12798 12798 12798 12798 12798 12798 12801 13821 min: 12729 cycles q1: 12744 cycles median: 12774 cycles q3: 12792 cycles max: 13821 cycles RESULT TestSetjmpLongjmp_CycleCount: trusted_mac_x86-64= {12774, 48} count Apparent clock speed: 2598 MHz TestClockGetTime: Measuring real time: 0.080 usec (8e-08 sec) per iteration: 8e-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.59908e-08 sec) per iteration: 0.101321 sec for 1333333 iterations 0.075 usec (7.53278e-08 sec) per iteration: 0.100437 sec for 1333333 iterations 0.075 usec (7.53188e-08 sec) per iteration: 0.100425 sec for 1333333 iterations 0.076 usec (7.60418e-08 sec) per iteration: 0.101389 sec for 1333333 iterations 0.075 usec (7.54748e-08 sec) per iteration: 0.100633 sec for 1333333 iterations mean: 0.075631 usec stddev: 0.000320 usec relative stddev: 0.42% RESULT TestClockGetTime: trusted_mac_x86-64= {0.075631, 0.000320} us Measuring clock cycles: first runs (cycles): 1170 216 198 201 198 198 195 204 201 198 ... slowest runs (cycles): ... 204 204 204 204 204 204 204 216 219 1170 min: 195 cycles q1: 198 cycles median: 198 cycles q3: 201 cycles max: 1170 cycles RESULT TestClockGetTime_CycleCount: trusted_mac_x86-64= {198, 3} count Apparent clock speed: 2618 MHz TestMmapAnonymous: Measuring real time: 3.770 usec (3.77e-06 sec) per iteration: 0.000377 sec for 100 iterations 3.112 usec (3.11152e-06 sec) per iteration: 0.082533 sec for 26525 iterations 3.157 usec (3.15672e-06 sec) per iteration: 0.083732 sec for 26525 iterations 3.135 usec (3.13512e-06 sec) per iteration: 0.083159 sec for 26525 iterations 3.123 usec (3.12332e-06 sec) per iteration: 0.082846 sec for 26525 iterations 3.126 usec (3.12558e-06 sec) per iteration: 0.082906 sec for 26525 iterations mean: 3.130451 usec stddev: 0.015132 usec relative stddev: 0.48% RESULT TestMmapAnonymous: trusted_mac_x86-64= {3.130451, 0.015132} us Measuring clock cycles: first runs (cycles): 11580 8514 8265 8262 8187 8214 8202 8226 8358 8205 ... slowest runs (cycles): ... 8550 8553 8562 8589 8589 8592 8598 8664 11580 48144 min: 8187 cycles q1: 8484 cycles median: 8514 cycles q3: 8529 cycles max: 48144 cycles RESULT TestMmapAnonymous_CycleCount: trusted_mac_x86-64= {8514, 45} count Apparent clock speed: 2720 MHz TestAtomicIncrement: Measuring real time: 0.010 usec (1e-08 sec) per iteration: 1e-06 sec for 100 iterations 0.007 usec (7e-09 sec) per iteration: 7e-06 sec for 1000 iterations 0.007 usec (7.4e-09 sec) per iteration: 7.4e-05 sec for 10000 iterations 0.007 usec (7.34036e-09 sec) per iteration: 0.099194 sec for 13513513 iterations 0.007 usec (7.2887e-09 sec) per iteration: 0.098496 sec for 13513513 iterations 0.007 usec (7.34961e-09 sec) per iteration: 0.099319 sec for 13513513 iterations 0.007 usec (7.2967e-09 sec) per iteration: 0.098604 sec for 13513513 iterations 0.007 usec (7.35257e-09 sec) per iteration: 0.099359 sec for 13513513 iterations mean: 0.007326 usec stddev: 0.000027 usec relative stddev: 0.37% RESULT TestAtomicIncrement: trusted_mac_x86-64= {0.007326, 0.000027} us Measuring clock cycles: first runs (cycles): 303 54 54 54 51 51 51 51 51 51 ... slowest runs (cycles): ... 51 51 51 51 51 54 54 54 66 303 min: 48 cycles q1: 48 cycles median: 51 cycles q3: 51 cycles max: 303 cycles RESULT TestAtomicIncrement_CycleCount: trusted_mac_x86-64= {51, 3} count Apparent clock speed: 6962 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.65408e-08 sec) per iteration: 0.012064 sec for 454545 iterations 0.027 usec (2.65562e-08 sec) per iteration: 0.012071 sec for 454545 iterations 0.026 usec (2.62196e-08 sec) per iteration: 0.011918 sec for 454545 iterations 0.025 usec (2.53726e-08 sec) per iteration: 0.011533 sec for 454545 iterations 0.027 usec (2.66068e-08 sec) per iteration: 0.012094 sec for 454545 iterations mean: 0.026259 usec stddev: 0.000464 usec relative stddev: 1.77% RESULT TestUncontendedMutexLock: trusted_mac_x86-64= {0.026259, 0.000464} us Measuring clock cycles: first runs (cycles): 438 120 93 87 87 93 93 96 96 93 ... slowest runs (cycles): ... 96 96 96 96 96 96 96 99 120 438 min: 84 cycles q1: 87 cycles median: 93 cycles q3: 96 cycles max: 438 cycles RESULT TestUncontendedMutexLock_CycleCount: trusted_mac_x86-64= {93, 9} count Apparent clock speed: 3542 MHz TestCondvarSignalNoOp: Measuring real time: 0.100 usec (1e-07 sec) per iteration: 1e-05 sec for 100 iterations 0.014 usec (1.392e-08 sec) per iteration: 0.01392 sec for 1000000 iterations 0.014 usec (1.3691e-08 sec) per iteration: 0.013691 sec for 1000000 iterations 0.014 usec (1.3915e-08 sec) per iteration: 0.013915 sec for 1000000 iterations 0.014 usec (1.4036e-08 sec) per iteration: 0.014036 sec for 1000000 iterations 0.014 usec (1.3858e-08 sec) per iteration: 0.013858 sec for 1000000 iterations mean: 0.013884 usec stddev: 0.000113 usec relative stddev: 0.81% RESULT TestCondvarSignalNoOp: trusted_mac_x86-64= {0.013884, 0.000113} us Measuring clock cycles: first runs (cycles): 483 87 60 60 63 63 72 63 63 63 ... slowest runs (cycles): ... 72 72 72 72 72 72 72 72 87 483 min: 60 cycles q1: 63 cycles median: 63 cycles q3: 63 cycles max: 483 cycles RESULT TestCondvarSignalNoOp_CycleCount: trusted_mac_x86-64= {63, 0} count Apparent clock speed: 4538 MHz TestThreadCreateAndJoin: Measuring real time: 84.780 usec (8.478e-05 sec) per iteration: 0.008478 sec for 100 iterations 82.533 usec (8.25327e-05 sec) per iteration: 0.097306 sec for 1179 iterations 82.972 usec (8.2972e-05 sec) per iteration: 0.097824 sec for 1179 iterations 82.634 usec (8.26344e-05 sec) per iteration: 0.097426 sec for 1179 iterations 82.338 usec (8.23384e-05 sec) per iteration: 0.097077 sec for 1179 iterations 83.467 usec (8.34673e-05 sec) per iteration: 0.098408 sec for 1179 iterations mean: 82.788974 usec stddev: 0.396552 usec relative stddev: 0.48% RESULT TestThreadCreateAndJoin: trusted_mac_x86-64= {82.788974, 0.396552} us Measuring clock cycles: first runs (cycles): 146985 286791 253935 155985 297576 275391 224337 240840 241068 239721 ... slowest runs (cycles): ... 260085 261153 261915 275391 280395 286791 294552 297576 309414 309567 min: 140577 cycles q1: 230061 cycles median: 238038 cycles q3: 247608 cycles max: 309567 cycles RESULT TestThreadCreateAndJoin_CycleCount: trusted_mac_x86-64= {238038, 17547} count Apparent clock speed: 2875 MHz TestThreadWakeup: Measuring real time: 21.550 usec (2.155e-05 sec) per iteration: 0.002155 sec for 100 iterations 19.835 usec (1.98351e-05 sec) per iteration: 0.092035 sec for 4640 iterations 19.576 usec (1.95759e-05 sec) per iteration: 0.090832 sec for 4640 iterations 20.032 usec (2.00317e-05 sec) per iteration: 0.092947 sec for 4640 iterations 20.132 usec (2.01323e-05 sec) per iteration: 0.093414 sec for 4640 iterations 19.878 usec (1.98782e-05 sec) per iteration: 0.092235 sec for 4640 iterations mean: 19.890647 usec stddev: 0.190066 usec relative stddev: 0.96% RESULT TestThreadWakeup: trusted_mac_x86-64= {19.890647, 0.190066} us Measuring clock cycles: first runs (cycles): 69963 52569 51096 52629 53694 51477 66315 38742 57897 68307 ... slowest runs (cycles): ... 61746 66315 66816 67707 68307 68850 69963 70923 71784 84960 min: 38742 cycles q1: 52314 cycles median: 52941 cycles q3: 54129 cycles max: 84960 cycles RESULT TestThreadWakeup_CycleCount: trusted_mac_x86-64= {52941, 1815} count Apparent clock speed: 2662 MHz WARNING: should have taken less than 2.000000 secs [ OK ] nacl_newlib.run_trusted_performance_test (3929 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