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

Running command: /b/s/w/ir/cache/vpython/7c7ecd/bin/python scons.py --verbose -k -j1 --mode=nacl,opt-host platform=x86-64 --clang large_tests force_sel_ldr=../out_64/sel_ldr force_irt=../out_64/irt_x64/irt_core.nexe perf_prefix=gn_ scons: Reading SConscript files ... ====================================================================== SCONS ARGS:['scons.py', '--verbose', '-k', '-j1', '--mode=nacl,opt-host', 'platform=x86-64', '--clang', 'large_tests', 'force_sel_ldr=../out_64/sel_ldr', 'force_irt=../out_64/irt_x64/irt_core.nexe', 'perf_prefix=gn_'] ====================================================================== ====================================================================== Python Info: ====================================================================== darwin 2.7.14+chromium14 (6cc0aad35b-dirty:6cc0aad35b, Oct 3 2017, 17:23:56) [GCC 4.2.1 Compatible Apple LLVM 8.0.0 (clang-800.0.38)] ====================================================================== ENV: ====================================================================== PATH /b/s/w/ir/cache/vpython/7c7ecd/bin:/b/s/w/ir/cipd_bin_packages:/b/s/w/ir/cipd_bin_packages/bin:/b/s/cipd_cache/bin:/opt/local/bin:/opt/local/sbin:/usr/local/sbin:/usr/local/git/bin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/b/s/w/ir/kitchen-checkout/depot_tools ====================================================================== OS: ====================================================================== kern.ostype: Darwin kern.osrelease: 17.5.0 kern.osrevision: 199506 kern.version: Darwin Kernel Version 17.5.0: Mon Mar 5 22:24:32 PST 2018; root:xnu-4570.51.1~1/RELEASE_X86_64 kern.posix1version: 200112 kern.osversion: 17E199 kern.osproductversion: 10.13.4 ====================================================================== CPU: ====================================================================== hw.machine: x86_64 hw.model: VMware7,1 hw.ncpu: 8 hw.ncpu: 8 hw.activecpu: 8 hw.physicalcpu: 8 hw.physicalcpu_max: 8 hw.logicalcpu: 8 hw.logicalcpu_max: 8 hw.cputype: 7 hw.cpusubtype: 4 hw.cpu64bit_capable: 1 hw.cpufamily: 526772277 hw.cpufrequency: 2574000000 hw.cpufrequency_min: 2574000000 hw.cpufrequency_max: 2574000000 ====================================================================== RAM: ====================================================================== hw.memsize: 17179869184 ====================================================================== LOAD: ====================================================================== TBD ====================================================================== UPTIME: ====================================================================== kern.boottime: { sec = 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 gn_x86-64_nnacl_newlib_static --subarch 64 --arch x86 --capture_output 0 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/test_results/benchmark_test.out /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -- scons-out/nacl-x86-64/obj/tests/benchmark/benchmark_test.nexe gn_x86-64_nnacl_newlib_static [ RUN ] nacl_newlib.run_benchmark_test /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -- scons-out/nacl-x86-64/obj/tests/benchmark/benchmark_test.nexe gn_x86-64_nnacl_newlib_static [46986,2635494272:15:32:29.804207] Native Client module will be loaded at base address 0x0000634400000000 Running suite of 1 benchmarks: Running Benchmark: Life (SIMD version)... RESULT BenchmarkLife: gn_x86-64_nnacl_newlib_static= {0.065160, 0.000980} seconds --------------------------------------------------------------- Done running benchmark suite. [ OK ] nacl_newlib.run_benchmark_test (850 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python tools/command_tester.py --name nacl_newlib.run_clock_cputime_test --time_warning 60 --time_error 600 --perf_env_description gn_x86-64_nnacl_newlib_static --subarch 64 --arch x86 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/test_results/clock_cputime_test.out /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -- scons-out/nacl-x86-64/obj/tests/clock/clock_test.nexe -c [ RUN ] nacl_newlib.run_clock_cputime_test /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -- scons-out/nacl-x86-64/obj/tests/clock/clock_test.nexe -c WARNING: should have taken less than 60.000000 secs [ OK ] nacl_newlib.run_clock_cputime_test (66350 ms) doSizeCheck(["scons-out/nacl-x86-64/obj/tests/hello_world/hello_world_size.out"], ["scons-out/nacl-x86-64/obj/tests/hello_world/hello_world.nexe"]) RESULT hello_world_size.out: gn_x86-64_nnacl_newlib_static= 525.260 KB RESULT hello_world_size.out: ZIPPED_gn_x86-64_nnacl_newlib_static= 187.859 KB /b/s/w/ir/cache/vpython/7c7ecd/bin/python tools/command_tester.py --name nacl_newlib.run_performance_test --time_warning 10 --time_error 100 --perf_env_description gn_x86-64_nnacl_newlib_static --subarch 64 --arch x86 --capture_output 0 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/test_results/performance_test.out /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -e -- scons-out/nacl-x86-64/obj/tests/performance/performance_test.nexe gn_x86-64_nnacl_newlib_static [ RUN ] nacl_newlib.run_performance_test /b/s/w/ir/kitchen-workdir/out_64/sel_ldr -e -- scons-out/nacl-x86-64/obj/tests/performance/performance_test.nexe gn_x86-64_nnacl_newlib_static [46991,2635494272:15:32:44.003238] Native Client module will be loaded at base address 0x00005d3b00000000 TestNull: Measuring real time: 0.007 usec (6.68e-09 sec) per iteration: 6.68e-07 sec for 100 iterations 0.002 usec (2.263e-09 sec) per iteration: 2.263e-06 sec for 1000 iterations 0.002 usec (2.0276e-09 sec) per iteration: 2.0276e-05 sec for 10000 iterations 0.002 usec (2.05014e-09 sec) per iteration: 0.101112 sec for 49319392 iterations 0.002 usec (2.04772e-09 sec) per iteration: 0.100992 sec for 49319392 iterations 0.002 usec (1.96576e-09 sec) per iteration: 0.0969499 sec for 49319392 iterations 0.002 usec (1.99572e-09 sec) per iteration: 0.0984278 sec for 49319392 iterations 0.002 usec (2.00362e-09 sec) per iteration: 0.0988175 sec for 49319392 iterations mean: 0.002013 usec stddev: 0.000032 usec relative stddev: 1.60% RESULT TestNull: gn_x86-64_nnacl_newlib_static= {0.002013, 0.000032} us Measuring clock cycles: first runs (cycles): 261 24 24 24 24 18 24 21 21 21 ... slowest runs (cycles): ... 24 24 24 24 24 24 24 24 24 261 min: 18 cycles q1: 21 cycles median: 21 cycles q3: 24 cycles max: 261 cycles RESULT TestNull_CycleCount: gn_x86-64_nnacl_newlib_static= {21, 3} count Apparent clock speed: 10434 MHz TestNaClSyscall: Measuring real time: 0.165 usec (1.6486e-07 sec) per iteration: 1.6486e-05 sec for 100 iterations 0.159 usec (1.58517e-07 sec) per iteration: 0.0961527 sec for 606575 iterations 0.158 usec (1.5799e-07 sec) per iteration: 0.0958327 sec for 606575 iterations 0.158 usec (1.57931e-07 sec) per iteration: 0.0957968 sec for 606575 iterations 0.154 usec (1.53739e-07 sec) per iteration: 0.093254 sec for 606575 iterations 0.169 usec (1.69234e-07 sec) per iteration: 0.102653 sec for 606575 iterations mean: 0.159482 usec stddev: 0.005170 usec relative stddev: 3.24% RESULT TestNaClSyscall: gn_x86-64_nnacl_newlib_static= {0.159482, 0.005170} us Measuring clock cycles: first runs (cycles): 753 312 282 300 294 294 300 297 303 294 ... slowest runs (cycles): ... 300 300 300 300 300 300 300 303 312 753 min: 279 cycles q1: 285 cycles median: 294 cycles q3: 300 cycles max: 753 cycles RESULT TestNaClSyscall_CycleCount: gn_x86-64_nnacl_newlib_static= {294, 15} count Apparent clock speed: 1843 MHz TestSetjmpLongjmp: Measuring real time: 0.016 usec (1.636e-08 sec) per iteration: 1.636e-06 sec for 100 iterations 0.012 usec (1.2349e-08 sec) per iteration: 1.2349e-05 sec for 1000 iterations 0.013 usec (1.28042e-08 sec) per iteration: 0.103686 sec for 8097821 iterations 0.012 usec (1.2307e-08 sec) per iteration: 0.0996597 sec for 8097821 iterations 0.012 usec (1.19498e-08 sec) per iteration: 0.0967677 sec for 8097821 iterations 0.012 usec (1.20367e-08 sec) per iteration: 0.0974714 sec for 8097821 iterations 0.012 usec (1.20821e-08 sec) per iteration: 0.097839 sec for 8097821 iterations mean: 0.012236 usec stddev: 0.000308 usec relative stddev: 2.51% RESULT TestSetjmpLongjmp: gn_x86-64_nnacl_newlib_static= {0.012236, 0.000308} us Measuring clock cycles: first runs (cycles): 444 33 33 24 24 24 33 30 33 33 ... slowest runs (cycles): ... 33 33 33 33 33 33 33 33 33 444 min: 21 cycles q1: 24 cycles median: 30 cycles q3: 33 cycles max: 444 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_x86-64_nnacl_newlib_static= {30, 9} count Apparent clock speed: 2452 MHz TestClockGetTime: Measuring real time: 0.160 usec (1.604e-07 sec) per iteration: 1.604e-05 sec for 100 iterations 0.157 usec (1.5703e-07 sec) per iteration: 0.097899 sec for 623441 iterations 0.159 usec (1.58602e-07 sec) per iteration: 0.0988793 sec for 623441 iterations 0.158 usec (1.57907e-07 sec) per iteration: 0.0984458 sec for 623441 iterations 0.158 usec (1.58194e-07 sec) per iteration: 0.0986245 sec for 623441 iterations 0.164 usec (1.6379e-07 sec) per iteration: 0.102113 sec for 623441 iterations mean: 0.159105 usec stddev: 0.002399 usec relative stddev: 1.51% RESULT TestClockGetTime: gn_x86-64_nnacl_newlib_static= {0.159105, 0.002399} us Measuring clock cycles: first runs (cycles): 1596 471 447 435 435 435 438 435 438 435 ... slowest runs (cycles): ... 444 444 447 447 447 447 450 450 471 1596 min: 432 cycles q1: 435 cycles median: 435 cycles q3: 438 cycles max: 1596 cycles RESULT TestClockGetTime_CycleCount: gn_x86-64_nnacl_newlib_static= {435, 3} count Apparent clock speed: 2734 MHz TestTlsVariable: Measuring real time: 0.010 usec (9.59e-09 sec) per iteration: 9.59e-07 sec for 100 iterations 0.006 usec (6.273e-09 sec) per iteration: 6.273e-06 sec for 1000 iterations 0.006 usec (6.0277e-09 sec) per iteration: 6.0277e-05 sec for 10000 iterations 0.006 usec (6.13947e-09 sec) per iteration: 0.101854 sec for 16590075 iterations 0.006 usec (6.07866e-09 sec) per iteration: 0.100845 sec for 16590075 iterations 0.006 usec (6.11687e-09 sec) per iteration: 0.101479 sec for 16590075 iterations 0.006 usec (5.97688e-09 sec) per iteration: 0.0991569 sec for 16590075 iterations 0.006 usec (6.23539e-09 sec) per iteration: 0.103446 sec for 16590075 iterations mean: 0.006109 usec stddev: 0.000084 usec relative stddev: 1.38% RESULT TestTlsVariable: gn_x86-64_nnacl_newlib_static= {0.006109, 0.000084} us Measuring clock cycles: first runs (cycles): 381 75 30 18 21 24 24 21 21 21 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 75 381 min: 18 cycles q1: 21 cycles median: 24 cycles q3: 30 cycles max: 381 cycles RESULT TestTlsVariable_CycleCount: gn_x86-64_nnacl_newlib_static= {24, 9} count Apparent clock speed: 3928 MHz TestMmapAnonymous: Measuring real time: 8.507 usec (8.5071e-06 sec) per iteration: 0.00085071 sec for 100 iterations 8.174 usec (8.17354e-06 sec) per iteration: 0.0960718 sec for 11754 iterations 8.262 usec (8.2616e-06 sec) per iteration: 0.0971069 sec for 11754 iterations 8.193 usec (8.19258e-06 sec) per iteration: 0.0962956 sec for 11754 iterations 8.192 usec (8.19236e-06 sec) per iteration: 0.096293 sec for 11754 iterations 8.217 usec (8.21683e-06 sec) per iteration: 0.0965807 sec for 11754 iterations mean: 8.207385 usec stddev: 0.030394 usec relative stddev: 0.37% RESULT TestMmapAnonymous: gn_x86-64_nnacl_newlib_static= {8.207385, 0.030394} us Measuring clock cycles: first runs (cycles): 31050 22938 23052 22518 22905 23352 22854 23685 22572 22497 ... slowest runs (cycles): ... 22746 22854 22881 22893 22905 22938 23052 23352 23685 31050 min: 21975 cycles q1: 22134 cycles median: 22245 cycles q3: 22425 cycles max: 31050 cycles RESULT TestMmapAnonymous_CycleCount: gn_x86-64_nnacl_newlib_static= {22245, 291} count Apparent clock speed: 2710 MHz TestAtomicIncrement: Measuring real time: 0.014 usec (1.377e-08 sec) per iteration: 1.377e-06 sec for 100 iterations 0.010 usec (9.908e-09 sec) per iteration: 9.908e-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.75586e-09 sec) per iteration: 0.100674 sec for 10319384 iterations 0.010 usec (9.62896e-09 sec) per iteration: 0.0993649 sec for 10319384 iterations 0.010 usec (9.90018e-09 sec) per iteration: 0.102164 sec for 10319384 iterations 0.010 usec (9.65289e-09 sec) per iteration: 0.0996118 sec for 10319384 iterations 0.010 usec (9.69435e-09 sec) per iteration: 0.10004 sec for 10319384 iterations mean: 0.009726 usec stddev: 0.000097 usec relative stddev: 1.00% RESULT TestAtomicIncrement: gn_x86-64_nnacl_newlib_static= {0.009726, 0.000097} us Measuring clock cycles: first runs (cycles): 306 48 51 42 48 51 48 51 48 51 ... slowest runs (cycles): ... 51 51 51 51 51 51 51 51 51 306 min: 39 cycles q1: 48 cycles median: 48 cycles q3: 51 cycles max: 306 cycles RESULT TestAtomicIncrement_CycleCount: gn_x86-64_nnacl_newlib_static= {48, 3} count Apparent clock speed: 4935 MHz TestUncontendedMutexLock: Measuring real time: 0.029 usec (2.862e-08 sec) per iteration: 2.862e-06 sec for 100 iterations 0.023 usec (2.3272e-08 sec) per iteration: 2.3272e-05 sec for 1000 iterations 0.023 usec (2.28774e-08 sec) per iteration: 0.0983044 sec for 4297009 iterations 0.023 usec (2.32007e-08 sec) per iteration: 0.0996936 sec for 4297009 iterations 0.023 usec (2.30215e-08 sec) per iteration: 0.0989238 sec for 4297009 iterations 0.024 usec (2.36387e-08 sec) per iteration: 0.101576 sec for 4297009 iterations 0.024 usec (2.36724e-08 sec) per iteration: 0.101721 sec for 4297009 iterations mean: 0.023282 usec stddev: 0.000322 usec relative stddev: 1.38% RESULT TestUncontendedMutexLock: gn_x86-64_nnacl_newlib_static= {0.023282, 0.000322} us Measuring clock cycles: first runs (cycles): 432 102 81 75 81 78 81 78 81 78 ... slowest runs (cycles): ... 81 81 81 81 81 81 81 81 102 432 min: 75 cycles q1: 78 cycles median: 81 cycles q3: 81 cycles max: 432 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_x86-64_nnacl_newlib_static= {81, 3} count Apparent clock speed: 3479 MHz TestCondvarSignalNoOp: Measuring real time: 0.281 usec (2.8091e-07 sec) per iteration: 2.8091e-05 sec for 100 iterations 0.159 usec (1.59429e-07 sec) per iteration: 0.0567545 sec for 355985 iterations 0.167 usec (1.67073e-07 sec) per iteration: 0.0594755 sec for 355985 iterations 0.163 usec (1.63076e-07 sec) per iteration: 0.0580524 sec for 355985 iterations 0.163 usec (1.62591e-07 sec) per iteration: 0.05788 sec for 355985 iterations 0.158 usec (1.57713e-07 sec) per iteration: 0.0561433 sec for 355985 iterations mean: 0.161976 usec stddev: 0.003232 usec relative stddev: 2.00% RESULT TestCondvarSignalNoOp: gn_x86-64_nnacl_newlib_static= {0.161976, 0.003232} us Measuring clock cycles: first runs (cycles): 1236 411 411 408 405 411 408 411 408 408 ... slowest runs (cycles): ... 411 411 411 411 414 414 414 414 432 1236 min: 405 cycles q1: 408 cycles median: 408 cycles q3: 411 cycles max: 1236 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_x86-64_nnacl_newlib_static= {408, 3} count Apparent clock speed: 2519 MHz TestThreadCreateAndJoin: Measuring real time: 65.055 usec (6.50551e-05 sec) per iteration: 0.00650551 sec for 100 iterations 66.865 usec (6.68646e-05 sec) per iteration: 0.102771 sec for 1537 iterations 64.153 usec (6.41526e-05 sec) per iteration: 0.0986025 sec for 1537 iterations 66.569 usec (6.65686e-05 sec) per iteration: 0.102316 sec for 1537 iterations 64.391 usec (6.43913e-05 sec) per iteration: 0.0989694 sec for 1537 iterations 63.950 usec (6.39504e-05 sec) per iteration: 0.0982918 sec for 1537 iterations mean: 65.185500 usec stddev: 1.261385 usec relative stddev: 1.94% RESULT TestThreadCreateAndJoin: gn_x86-64_nnacl_newlib_static= {65.185500, 1.261385} us Measuring clock cycles: first runs (cycles): 181263 178752 202497 251283 187569 219735 184755 184224 171177 172704 ... slowest runs (cycles): ... 183558 184224 184755 185094 187569 191577 202497 206058 219735 251283 min: 166452 cycles q1: 169989 cycles median: 171228 cycles q3: 173136 cycles max: 251283 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_x86-64_nnacl_newlib_static= {171228, 3147} count Apparent clock speed: 2627 MHz TestThreadWakeup: Measuring real time: 30.422 usec (3.04223e-05 sec) per iteration: 0.00304223 sec for 100 iterations 30.518 usec (3.0518e-05 sec) per iteration: 0.100313 sec for 3287 iterations 29.983 usec (2.99827e-05 sec) per iteration: 0.0985532 sec for 3287 iterations 30.222 usec (3.02221e-05 sec) per iteration: 0.0993399 sec for 3287 iterations 30.210 usec (3.02097e-05 sec) per iteration: 0.0992991 sec for 3287 iterations 30.124 usec (3.01242e-05 sec) per iteration: 0.0990181 sec for 3287 iterations mean: 30.211323 usec stddev: 0.175520 usec relative stddev: 0.58% RESULT TestThreadWakeup: gn_x86-64_nnacl_newlib_static= {30.211323, 0.175520} us Measuring clock cycles: first runs (cycles): 83715 83997 83481 98313 117942 175590 105552 99771 94023 73815 ... slowest runs (cycles): ... 88896 90504 92331 94023 98313 99771 103002 105552 117942 175590 min: 73038 cycles q1: 80907 cycles median: 81480 cycles q3: 82953 cycles max: 175590 cycles RESULT TestThreadWakeup_CycleCount: gn_x86-64_nnacl_newlib_static= {81480, 2046} count Apparent clock speed: 2697 MHz TestCatchingFault: Measuring real time: 35.381 usec (3.5381e-05 sec) per iteration: 0.0035381 sec for 100 iterations 30.796 usec (3.07958e-05 sec) per iteration: 0.0870289 sec for 2826 iterations 32.191 usec (3.21912e-05 sec) per iteration: 0.0909723 sec for 2826 iterations 30.842 usec (3.08418e-05 sec) per iteration: 0.0871589 sec for 2826 iterations 30.895 usec (3.08946e-05 sec) per iteration: 0.0873081 sec for 2826 iterations 30.828 usec (3.08279e-05 sec) per iteration: 0.0871197 sec for 2826 iterations mean: 31.110255 usec stddev: 0.541399 usec relative stddev: 1.74% RESULT TestCatchingFault: gn_x86-64_nnacl_newlib_static= {31.110255, 0.541399} us Measuring clock cycles: first runs (cycles): 103554 85065 89370 106854 126453 170160 113343 139806 119859 94476 ... slowest runs (cycles): ... 100536 101619 103554 106854 107187 113343 119859 126453 139806 170160 min: 80964 cycles q1: 81918 cycles median: 82263 cycles q3: 83079 cycles max: 170160 cycles RESULT TestCatchingFault_CycleCount: gn_x86-64_nnacl_newlib_static= {82263, 1161} count Apparent clock speed: 2644 MHz TestThreadCreateAndJoinAfterSettingFaultHandler: Measuring real time: 65.586 usec (6.55861e-05 sec) per iteration: 0.00655861 sec for 100 iterations 63.915 usec (6.39147e-05 sec) per iteration: 0.097406 sec for 1524 iterations 63.761 usec (6.37605e-05 sec) per iteration: 0.097171 sec for 1524 iterations 64.025 usec (6.40254e-05 sec) per iteration: 0.0975747 sec for 1524 iterations 64.096 usec (6.40964e-05 sec) per iteration: 0.0976829 sec for 1524 iterations 64.022 usec (6.40222e-05 sec) per iteration: 0.0975699 sec for 1524 iterations mean: 63.963838 usec stddev: 0.117076 usec relative stddev: 0.18% RESULT TestThreadCreateAndJoinAfterSettingFaultHandler: gn_x86-64_nnacl_newlib_static= {63.963838, 0.117076} us Measuring clock cycles: first runs (cycles): 218478 239811 209277 243936 220395 190092 196608 181104 175098 173031 ... slowest runs (cycles): ... 193017 196287 196608 204078 209277 218478 220395 234933 239811 243936 min: 159378 cycles q1: 168387 cycles median: 169779 cycles q3: 172032 cycles max: 243936 cycles RESULT TestThreadCreateAndJoinAfterSettingFaultHandler_CycleCount: gn_x86-64_nnacl_newlib_static= {169779, 3645} count Apparent clock speed: 2654 MHz [ OK ] nacl_newlib.run_performance_test (6560 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python /b/s/w/ir/kitchen-workdir/native_client/tools/command_tester.py --name nacl_newlib.run_nacl_clock_cputime_test --time_warning 60 --time_error 600 --perf_env_description gn_trusted_mac_x86-64 --subarch 64 --arch x86 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/test_results/nacl_clock_cputime_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/src/shared/platform/nacl_clock_test -c [ RUN ] nacl_newlib.run_nacl_clock_cputime_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/src/shared/platform/nacl_clock_test -c [ OK ] nacl_newlib.run_nacl_clock_cputime_test (1510 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python /b/s/w/ir/kitchen-workdir/native_client/tools/command_tester.py --name nacl_newlib.run_nacl_interval_multi_reg_test --time_warning 60 --time_error 600 --perf_env_description gn_trusted_mac_x86-64 --subarch 64 --arch x86 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/test_results/nacl_interval_multi_reg_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/src/trusted/interval_multiset/nacl_interval_test -k NaClIntervalListMultiset -k NaClIntervalRangeTree -c 1000000 [ RUN ] nacl_newlib.run_nacl_interval_multi_reg_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/src/trusted/interval_multiset/nacl_interval_test -k NaClIntervalListMultiset -k NaClIntervalRangeTree -c 1000000 [ OK ] nacl_newlib.run_nacl_interval_multi_reg_test (720 ms) /b/s/w/ir/cache/vpython/7c7ecd/bin/python /b/s/w/ir/kitchen-workdir/native_client/tools/command_tester.py --name nacl_newlib.run_trusted_performance_test --time_warning 2 --time_error 20 --perf_env_description gn_trusted_mac_x86-64 --subarch 64 --arch x86 --capture_output 0 --output_stamp /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/test_results/performance_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/tests/performance/performance_test gn_trusted_mac_x86-64 [ RUN ] nacl_newlib.run_trusted_performance_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/opt-mac-x86-64/obj/tests/performance/performance_test gn_trusted_mac_x86-64 TestNull: Measuring real time: 0.010 usec (1e-08 sec) per iteration: 1e-06 sec for 100 iterations 0.003 usec (3e-09 sec) per iteration: 3e-06 sec for 1000 iterations 0.003 usec (2.6e-09 sec) per iteration: 2.6e-05 sec for 10000 iterations 0.003 usec (2.66256e-09 sec) per iteration: 0.102406 sec for 38461538 iterations 0.003 usec (2.67842e-09 sec) per iteration: 0.103016 sec for 38461538 iterations 0.003 usec (2.73302e-09 sec) per iteration: 0.105116 sec for 38461538 iterations 0.003 usec (2.67478e-09 sec) per iteration: 0.102876 sec for 38461538 iterations 0.003 usec (2.65517e-09 sec) per iteration: 0.102122 sec for 38461538 iterations mean: 0.002681 usec stddev: 0.000027 usec relative stddev: 1.02% RESULT TestNull: gn_trusted_mac_x86-64= {0.002681, 0.000027} us Measuring clock cycles: first runs (cycles): 264 27 30 18 21 18 21 18 30 27 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 30 264 min: 18 cycles q1: 18 cycles median: 27 cycles q3: 30 cycles max: 264 cycles RESULT TestNull_CycleCount: gn_trusted_mac_x86-64= {27, 12} count Apparent clock speed: 10072 MHz TestHostSyscall: Measuring real time: 1.150 usec (1.15e-06 sec) per iteration: 0.000115 sec for 100 iterations 1.001 usec (1.00097e-06 sec) per iteration: 0.08704 sec for 86956 iterations 1.001 usec (1.00107e-06 sec) per iteration: 0.087049 sec for 86956 iterations 1.004 usec (1.00449e-06 sec) per iteration: 0.087346 sec for 86956 iterations 0.985 usec (9.85165e-07 sec) per iteration: 0.085666 sec for 86956 iterations 1.024 usec (1.02443e-06 sec) per iteration: 0.08908 sec for 86956 iterations mean: 1.003222 usec stddev: 0.012546 usec relative stddev: 1.25% RESULT TestHostSyscall: gn_trusted_mac_x86-64= {1.003222, 0.012546} us Measuring clock cycles: first runs (cycles): 3138 2793 2757 2748 2748 2748 2748 2748 2748 2748 ... slowest runs (cycles): ... 2781 2781 2781 2781 2781 2781 2781 2790 2793 3138 min: 2739 cycles q1: 2748 cycles median: 2769 cycles q3: 2772 cycles max: 3138 cycles RESULT TestHostSyscall_CycleCount: gn_trusted_mac_x86-64= {2769, 24} count Apparent clock speed: 2760 MHz TestSetjmpLongjmp: Measuring real time: 5.270 usec (5.27e-06 sec) per iteration: 0.000527 sec for 100 iterations 4.953 usec (4.95267e-06 sec) per iteration: 0.093977 sec for 18975 iterations 4.952 usec (4.95194e-06 sec) per iteration: 0.093963 sec for 18975 iterations 4.943 usec (4.94324e-06 sec) per iteration: 0.093798 sec for 18975 iterations 4.945 usec (4.94451e-06 sec) per iteration: 0.093822 sec for 18975 iterations 4.742 usec (4.74187e-06 sec) per iteration: 0.089977 sec for 18975 iterations mean: 4.906846 usec stddev: 0.082575 usec relative stddev: 1.68% RESULT TestSetjmpLongjmp: gn_trusted_mac_x86-64= {4.906846, 0.082575} us Measuring clock cycles: first runs (cycles): 14208 13242 13290 13278 13311 13278 13305 13275 13302 13281 ... slowest runs (cycles): ... 13320 13323 13323 13323 13323 13323 13326 13326 13326 14208 min: 13242 cycles q1: 13290 cycles median: 13302 cycles q3: 13308 cycles max: 14208 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_trusted_mac_x86-64= {13302, 18} count Apparent clock speed: 2711 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.076 usec (7.58958e-08 sec) per iteration: 0.098566 sec for 1298701 iterations 0.076 usec (7.60722e-08 sec) per iteration: 0.098795 sec for 1298701 iterations 0.076 usec (7.56048e-08 sec) per iteration: 0.098188 sec for 1298701 iterations 0.076 usec (7.56625e-08 sec) per iteration: 0.098263 sec for 1298701 iterations 0.077 usec (7.65388e-08 sec) per iteration: 0.099401 sec for 1298701 iterations mean: 0.075955 usec stddev: 0.000337 usec relative stddev: 0.44% RESULT TestClockGetTime: gn_trusted_mac_x86-64= {0.075955, 0.000337} us Measuring clock cycles: first runs (cycles): 1569 237 213 210 210 210 213 210 213 210 ... slowest runs (cycles): ... 213 213 213 213 213 213 216 237 240 1569 min: 201 cycles q1: 210 cycles median: 210 cycles q3: 210 cycles max: 1569 cycles RESULT TestClockGetTime_CycleCount: gn_trusted_mac_x86-64= {210, 0} count Apparent clock speed: 2765 MHz TestMmapAnonymous: Measuring real time: 3.770 usec (3.77e-06 sec) per iteration: 0.000377 sec for 100 iterations 3.010 usec (3.00984e-06 sec) per iteration: 0.079836 sec for 26525 iterations 3.050 usec (3.04984e-06 sec) per iteration: 0.080897 sec for 26525 iterations 3.047 usec (3.04739e-06 sec) per iteration: 0.080832 sec for 26525 iterations 3.060 usec (3.06002e-06 sec) per iteration: 0.081167 sec for 26525 iterations 3.068 usec (3.06752e-06 sec) per iteration: 0.081366 sec for 26525 iterations mean: 3.046922 usec stddev: 0.019898 usec relative stddev: 0.65% RESULT TestMmapAnonymous: gn_trusted_mac_x86-64= {3.046922, 0.019898} us Measuring clock cycles: first runs (cycles): 12036 8733 8256 8232 8448 8232 8214 8238 8238 8229 ... slowest runs (cycles): ... 14196 14208 14220 14268 14367 14439 14472 14562 14622 14886 min: 8214 cycles q1: 8298 cycles median: 12504 cycles q3: 13281 cycles max: 14886 cycles RESULT TestMmapAnonymous_CycleCount: gn_trusted_mac_x86-64= {12504, 4983} count Apparent clock speed: 4104 MHz TestAtomicIncrement: Measuring real time: 0.020 usec (2e-08 sec) per iteration: 2e-06 sec for 100 iterations 0.008 usec (8e-09 sec) per iteration: 8e-06 sec for 1000 iterations 0.008 usec (8.2e-09 sec) per iteration: 8.2e-05 sec for 10000 iterations 0.007 usec (7.36557e-09 sec) per iteration: 0.089824 sec for 12195121 iterations 0.007 usec (7.32588e-09 sec) per iteration: 0.08934 sec for 12195121 iterations 0.007 usec (7.28283e-09 sec) per iteration: 0.088815 sec for 12195121 iterations 0.007 usec (7.33679e-09 sec) per iteration: 0.089473 sec for 12195121 iterations 0.007 usec (7.46479e-09 sec) per iteration: 0.091034 sec for 12195121 iterations mean: 0.007355 usec stddev: 0.000061 usec relative stddev: 0.83% RESULT TestAtomicIncrement: gn_trusted_mac_x86-64= {0.007355, 0.000061} us Measuring clock cycles: first runs (cycles): 384 54 54 54 54 54 54 54 39 48 ... slowest runs (cycles): ... 48 54 54 54 54 54 54 54 63 384 min: 39 cycles q1: 39 cycles median: 48 cycles q3: 48 cycles max: 384 cycles RESULT TestAtomicIncrement_CycleCount: gn_trusted_mac_x86-64= {48, 9} count Apparent clock speed: 6526 MHz TestUncontendedMutexLock: Measuring real time: 0.210 usec (2.1e-07 sec) per iteration: 2.1e-05 sec for 100 iterations 0.027 usec (2.65545e-08 sec) per iteration: 0.012645 sec for 476190 iterations 0.027 usec (2.7363e-08 sec) per iteration: 0.01303 sec for 476190 iterations 0.027 usec (2.65419e-08 sec) per iteration: 0.012639 sec for 476190 iterations 0.027 usec (2.65587e-08 sec) per iteration: 0.012647 sec for 476190 iterations 0.027 usec (2.65524e-08 sec) per iteration: 0.012644 sec for 476190 iterations mean: 0.026714 usec stddev: 0.000324 usec relative stddev: 1.21% RESULT TestUncontendedMutexLock: gn_trusted_mac_x86-64= {0.026714, 0.000324} us Measuring clock cycles: first runs (cycles): 489 102 84 96 96 93 93 87 87 93 ... slowest runs (cycles): ... 96 96 96 96 96 96 96 102 111 489 min: 84 cycles q1: 87 cycles median: 93 cycles q3: 96 cycles max: 489 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_trusted_mac_x86-64= {93, 9} count Apparent clock speed: 3481 MHz TestCondvarSignalNoOp: Measuring real time: 0.100 usec (1e-07 sec) per iteration: 1e-05 sec for 100 iterations 0.014 usec (1.3856e-08 sec) per iteration: 0.013856 sec for 1000000 iterations 0.014 usec (1.3685e-08 sec) per iteration: 0.013685 sec for 1000000 iterations 0.014 usec (1.3518e-08 sec) per iteration: 0.013518 sec for 1000000 iterations 0.014 usec (1.3627e-08 sec) per iteration: 0.013627 sec for 1000000 iterations 0.014 usec (1.3696e-08 sec) per iteration: 0.013696 sec for 1000000 iterations mean: 0.013676 usec stddev: 0.000110 usec relative stddev: 0.80% RESULT TestCondvarSignalNoOp: gn_trusted_mac_x86-64= {0.013676, 0.000110} us Measuring clock cycles: first runs (cycles): 606 84 69 60 60 60 60 60 60 60 ... slowest runs (cycles): ... 69 69 69 69 69 69 69 75 84 606 min: 60 cycles q1: 60 cycles median: 60 cycles q3: 60 cycles max: 606 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_trusted_mac_x86-64= {60, 0} count Apparent clock speed: 4387 MHz TestThreadCreateAndJoin: Measuring real time: 83.580 usec (8.358e-05 sec) per iteration: 0.008358 sec for 100 iterations 81.510 usec (8.151e-05 sec) per iteration: 0.097486 sec for 1196 iterations 79.982 usec (7.99824e-05 sec) per iteration: 0.095659 sec for 1196 iterations 80.610 usec (8.06095e-05 sec) per iteration: 0.096409 sec for 1196 iterations 83.618 usec (8.36179e-05 sec) per iteration: 0.100007 sec for 1196 iterations 83.013 usec (8.30134e-05 sec) per iteration: 0.099284 sec for 1196 iterations mean: 81.746656 usec stddev: 1.383301 usec relative stddev: 1.69% RESULT TestThreadCreateAndJoin: gn_trusted_mac_x86-64= {81.746656, 1.383301} us Measuring clock cycles: first runs (cycles): 252687 253896 146760 159843 255294 158022 276996 236676 238491 235683 ... slowest runs (cycles): ... 276261 276315 276996 281823 287835 293892 300276 312102 320598 329004 min: 136182 cycles q1: 191742 cycles median: 231384 cycles q3: 251973 cycles max: 329004 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_trusted_mac_x86-64= {231384, 60231} count Apparent clock speed: 2831 MHz TestThreadWakeup: Measuring real time: 21.750 usec (2.175e-05 sec) per iteration: 0.002175 sec for 100 iterations 19.811 usec (1.98107e-05 sec) per iteration: 0.09107 sec for 4597 iterations 19.533 usec (1.95325e-05 sec) per iteration: 0.089791 sec for 4597 iterations 19.662 usec (1.96615e-05 sec) per iteration: 0.090384 sec for 4597 iterations 19.585 usec (1.95845e-05 sec) per iteration: 0.09003 sec for 4597 iterations 19.635 usec (1.96348e-05 sec) per iteration: 0.090261 sec for 4597 iterations mean: 19.644812 usec stddev: 0.093978 usec relative stddev: 0.48% RESULT TestThreadWakeup: gn_trusted_mac_x86-64= {19.644812, 0.093978} us Measuring clock cycles: first runs (cycles): 62493 53853 52017 67863 54888 52134 56598 67956 76935 70863 ... slowest runs (cycles): ... 65541 66273 66546 67863 67956 70863 71130 76935 80220 95034 min: 50676 cycles q1: 52335 cycles median: 53025 cycles q3: 55077 cycles max: 95034 cycles RESULT TestThreadWakeup_CycleCount: gn_trusted_mac_x86-64= {53025, 2742} count Apparent clock speed: 2699 MHz WARNING: should have taken less than 2.000000 secs [ OK ] nacl_newlib.run_trusted_performance_test (3930 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