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

Running command: /b/s/w/ir/cache/vpython/46fcd9/bin/python scons.py --verbose -k -j1 --mode=nacl,opt-host platform=x86-64 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', '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/46fcd9/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 = 1542824546, usec = 251731 } Wed Nov 21 10:22:26 2018 ====================================================================== The following environments have been configured ====================================================================== NACL_BUILD_FAMILY: UNTRUSTED BUILD_TYPE: nacl TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/obj BUILD_TYPE_DESCRIPTION: NaCl module build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang ASPPCOM: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_GNU_SOURCE=1 -D_POSIX_C_SOURCE=199506 -D_XOPEN_SOURCE=600 -DDYNAMIC_ANNOTATIONS_ENABLED=1 -DDYNAMIC_ANNOTATIONS_PREFIX=NACL_ -DNACL_BUILD_ARCH=x86 -DNACL_BUILD_SUBARCH=64 -I/b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/include -I/b/s/w/ir/kitchen-workdir -c -o UNKNOWN COMPILER NACL_BUILD_FAMILY: TRUSTED BUILD_TYPE: 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/46fcd9/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 [29219,2332877696:13:00:54.969985] Native Client module will be loaded at base address 0x00007dfc00000000 Running suite of 1 benchmarks: Running Benchmark: Life (SIMD version)... RESULT BenchmarkLife: gn_x86-64_nnacl_newlib_static= {0.065560, 0.002210} seconds --------------------------------------------------------------- Done running benchmark suite. [ OK ] nacl_newlib.run_benchmark_test (870 ms) /b/s/w/ir/cache/vpython/46fcd9/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 (66220 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= 528.080 KB RESULT hello_world_size.out: ZIPPED_gn_x86-64_nnacl_newlib_static= 187.899 KB /b/s/w/ir/cache/vpython/46fcd9/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 [29224,2332877696:13:01:09.111985] Native Client module will be loaded at base address 0x00000e0600000000 TestNull: Measuring real time: 0.007 usec (6.66e-09 sec) per iteration: 6.66e-07 sec for 100 iterations 0.002 usec (2.245e-09 sec) per iteration: 2.245e-06 sec for 1000 iterations 0.002 usec (2.0244e-09 sec) per iteration: 2.0244e-05 sec for 10000 iterations 0.002 usec (1.94546e-09 sec) per iteration: 0.0961005 sec for 49397352 iterations 0.002 usec (1.99069e-09 sec) per iteration: 0.0983347 sec for 49397352 iterations 0.002 usec (1.99057e-09 sec) per iteration: 0.0983291 sec for 49397352 iterations 0.002 usec (2.14322e-09 sec) per iteration: 0.105869 sec for 49397352 iterations 0.002 usec (2.09871e-09 sec) per iteration: 0.103671 sec for 49397352 iterations mean: 0.002034 usec stddev: 0.000074 usec relative stddev: 3.66% RESULT TestNull: gn_x86-64_nnacl_newlib_static= {0.002034, 0.000074} us Measuring clock cycles: first runs (cycles): 252 21 21 24 24 24 24 24 24 24 ... slowest runs (cycles): ... 24 24 24 24 24 24 24 24 24 252 min: 21 cycles q1: 24 cycles median: 24 cycles q3: 24 cycles max: 252 cycles RESULT TestNull_CycleCount: gn_x86-64_nnacl_newlib_static= {24, 0} count Apparent clock speed: 11801 MHz TestNaClSyscall: Measuring real time: 0.295 usec (2.9473e-07 sec) per iteration: 2.9473e-05 sec for 100 iterations 0.151 usec (1.50693e-07 sec) per iteration: 0.0511289 sec for 339293 iterations 0.154 usec (1.5381e-07 sec) per iteration: 0.0521868 sec for 339293 iterations 0.151 usec (1.50975e-07 sec) per iteration: 0.0512248 sec for 339293 iterations 0.147 usec (1.4663e-07 sec) per iteration: 0.0497506 sec for 339293 iterations 0.149 usec (1.4914e-07 sec) per iteration: 0.0506021 sec for 339293 iterations mean: 0.150250 usec stddev: 0.002355 usec relative stddev: 1.57% RESULT TestNaClSyscall: gn_x86-64_nnacl_newlib_static= {0.150250, 0.002355} us Measuring clock cycles: first runs (cycles): 687 282 279 264 261 270 264 264 270 261 ... slowest runs (cycles): ... 273 273 273 273 273 276 276 279 282 687 min: 261 cycles q1: 264 cycles median: 267 cycles q3: 273 cycles max: 687 cycles RESULT TestNaClSyscall_CycleCount: gn_x86-64_nnacl_newlib_static= {267, 9} count Apparent clock speed: 1777 MHz TestSetjmpLongjmp: Measuring real time: 0.016 usec (1.632e-08 sec) per iteration: 1.632e-06 sec for 100 iterations 0.012 usec (1.2382e-08 sec) per iteration: 1.2382e-05 sec for 1000 iterations 0.012 usec (1.16902e-08 sec) per iteration: 0.0944126 sec for 8076239 iterations 0.012 usec (1.21242e-08 sec) per iteration: 0.0979181 sec for 8076239 iterations 0.012 usec (1.21577e-08 sec) per iteration: 0.0981881 sec for 8076239 iterations 0.012 usec (1.17066e-08 sec) per iteration: 0.0945457 sec for 8076239 iterations 0.012 usec (1.21437e-08 sec) per iteration: 0.0980754 sec for 8076239 iterations mean: 0.011964 usec stddev: 0.000218 usec relative stddev: 1.82% RESULT TestSetjmpLongjmp: gn_x86-64_nnacl_newlib_static= {0.011964, 0.000218} us Measuring clock cycles: first runs (cycles): 426 57 33 21 24 24 33 33 33 33 ... slowest runs (cycles): ... 33 33 33 33 33 33 33 33 57 426 min: 21 cycles q1: 24 cycles median: 33 cycles q3: 33 cycles max: 426 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_x86-64_nnacl_newlib_static= {33, 9} count Apparent clock speed: 2758 MHz TestClockGetTime: Measuring real time: 0.168 usec (1.6754e-07 sec) per iteration: 1.6754e-05 sec for 100 iterations 0.161 usec (1.61461e-07 sec) per iteration: 0.0963713 sec for 596872 iterations 0.154 usec (1.53948e-07 sec) per iteration: 0.091887 sec for 596872 iterations 0.150 usec (1.50131e-07 sec) per iteration: 0.0896088 sec for 596872 iterations 0.170 usec (1.69694e-07 sec) per iteration: 0.101286 sec for 596872 iterations 0.153 usec (1.5331e-07 sec) per iteration: 0.0915064 sec for 596872 iterations mean: 0.157709 usec stddev: 0.007052 usec relative stddev: 4.47% RESULT TestClockGetTime: gn_x86-64_nnacl_newlib_static= {0.157709, 0.007052} us Measuring clock cycles: first runs (cycles): 1560 447 435 438 438 435 432 432 438 435 ... slowest runs (cycles): ... 444 444 444 444 444 444 447 447 447 1560 min: 420 cycles q1: 432 cycles median: 435 cycles q3: 438 cycles max: 1560 cycles RESULT TestClockGetTime_CycleCount: gn_x86-64_nnacl_newlib_static= {435, 6} count Apparent clock speed: 2758 MHz TestTlsVariable: Measuring real time: 0.010 usec (1.034e-08 sec) per iteration: 1.034e-06 sec for 100 iterations 0.006 usec (6.276e-09 sec) per iteration: 6.276e-06 sec for 1000 iterations 0.006 usec (6.0261e-09 sec) per iteration: 6.0261e-05 sec for 10000 iterations 0.006 usec (5.93017e-09 sec) per iteration: 0.0984082 sec for 16594480 iterations 0.006 usec (5.90725e-09 sec) per iteration: 0.0980277 sec for 16594480 iterations 0.006 usec (5.96709e-09 sec) per iteration: 0.0990208 sec for 16594480 iterations 0.006 usec (6.166e-09 sec) per iteration: 0.102322 sec for 16594480 iterations 0.006 usec (5.93449e-09 sec) per iteration: 0.0984797 sec for 16594480 iterations mean: 0.005981 usec stddev: 0.000094 usec relative stddev: 1.58% RESULT TestTlsVariable: gn_x86-64_nnacl_newlib_static= {0.005981, 0.000094} us Measuring clock cycles: first runs (cycles): 345 66 30 30 33 30 21 21 21 21 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 33 66 345 min: 21 cycles q1: 21 cycles median: 30 cycles q3: 30 cycles max: 345 cycles RESULT TestTlsVariable_CycleCount: gn_x86-64_nnacl_newlib_static= {30, 9} count Apparent clock speed: 5016 MHz TestMmapAnonymous: Measuring real time: 8.580 usec (8.5796e-06 sec) per iteration: 0.00085796 sec for 100 iterations 8.061 usec (8.06134e-06 sec) per iteration: 0.093955 sec for 11655 iterations 8.268 usec (8.26826e-06 sec) per iteration: 0.0963666 sec for 11655 iterations 8.515 usec (8.51532e-06 sec) per iteration: 0.099246 sec for 11655 iterations 8.418 usec (8.41795e-06 sec) per iteration: 0.0981112 sec for 11655 iterations 8.126 usec (8.12595e-06 sec) per iteration: 0.094708 sec for 11655 iterations mean: 8.277766 usec stddev: 0.170915 usec relative stddev: 2.06% RESULT TestMmapAnonymous: gn_x86-64_nnacl_newlib_static= {8.277766, 0.170915} us Measuring clock cycles: first runs (cycles): 30771 22677 21792 21771 21786 60273 21015 21150 21096 21081 ... slowest runs (cycles): ... 22686 22698 22755 22770 22803 22839 30771 60273 61653 62169 min: 21012 cycles q1: 22368 cycles median: 22476 cycles q3: 22548 cycles max: 62169 cycles RESULT TestMmapAnonymous_CycleCount: gn_x86-64_nnacl_newlib_static= {22476, 180} count Apparent clock speed: 2715 MHz TestAtomicIncrement: Measuring real time: 0.014 usec (1.38e-08 sec) per iteration: 1.38e-06 sec for 100 iterations 0.010 usec (9.893e-09 sec) per iteration: 9.893e-06 sec for 1000 iterations 0.010 usec (9.6887e-09 sec) per iteration: 9.6887e-05 sec for 10000 iterations 0.010 usec (9.53362e-09 sec) per iteration: 0.0983993 sec for 10321302 iterations 0.010 usec (9.6822e-09 sec) per iteration: 0.0999329 sec for 10321302 iterations 0.009 usec (9.46534e-09 sec) per iteration: 0.0976946 sec for 10321302 iterations 0.009 usec (9.488e-09 sec) per iteration: 0.0979285 sec for 10321302 iterations 0.010 usec (9.56429e-09 sec) per iteration: 0.0987159 sec for 10321302 iterations mean: 0.009547 usec stddev: 0.000076 usec relative stddev: 0.80% RESULT TestAtomicIncrement: gn_x86-64_nnacl_newlib_static= {0.009547, 0.000076} us Measuring clock cycles: first runs (cycles): 315 48 51 51 48 51 48 51 48 42 ... slowest runs (cycles): ... 51 51 51 51 51 51 51 51 51 315 min: 39 cycles q1: 48 cycles median: 48 cycles q3: 51 cycles max: 315 cycles RESULT TestAtomicIncrement_CycleCount: gn_x86-64_nnacl_newlib_static= {48, 3} count Apparent clock speed: 5028 MHz TestUncontendedMutexLock: Measuring real time: 0.028 usec (2.764e-08 sec) per iteration: 2.764e-06 sec for 100 iterations 0.023 usec (2.3267e-08 sec) per iteration: 2.3267e-05 sec for 1000 iterations 0.022 usec (2.24724e-08 sec) per iteration: 0.0965847 sec for 4297932 iterations 0.022 usec (2.19421e-08 sec) per iteration: 0.0943056 sec for 4297932 iterations 0.023 usec (2.25935e-08 sec) per iteration: 0.0971054 sec for 4297932 iterations 0.023 usec (2.3085e-08 sec) per iteration: 0.0992178 sec for 4297932 iterations 0.023 usec (2.27511e-08 sec) per iteration: 0.0977825 sec for 4297932 iterations mean: 0.022569 usec stddev: 0.000375 usec relative stddev: 1.66% RESULT TestUncontendedMutexLock: gn_x86-64_nnacl_newlib_static= {0.022569, 0.000375} us Measuring clock cycles: first runs (cycles): 444 108 69 72 69 87 84 87 84 87 ... slowest runs (cycles): ... 87 87 87 87 87 87 87 87 108 444 min: 69 cycles q1: 84 cycles median: 87 cycles q3: 87 cycles max: 444 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_x86-64_nnacl_newlib_static= {87, 3} count Apparent clock speed: 3855 MHz TestCondvarSignalNoOp: Measuring real time: 0.254 usec (2.5447e-07 sec) per iteration: 2.5447e-05 sec for 100 iterations 0.158 usec (1.58158e-07 sec) per iteration: 0.0621519 sec for 392973 iterations 0.158 usec (1.58456e-07 sec) per iteration: 0.0622688 sec for 392973 iterations 0.161 usec (1.61394e-07 sec) per iteration: 0.0634236 sec for 392973 iterations 0.162 usec (1.62035e-07 sec) per iteration: 0.0636755 sec for 392973 iterations 0.155 usec (1.54997e-07 sec) per iteration: 0.0609097 sec for 392973 iterations mean: 0.159008 usec stddev: 0.002529 usec relative stddev: 1.59% RESULT TestCondvarSignalNoOp: gn_x86-64_nnacl_newlib_static= {0.159008, 0.002529} us Measuring clock cycles: first runs (cycles): 1407 438 432 432 435 432 435 447 435 435 ... slowest runs (cycles): ... 438 438 438 438 438 444 444 447 447 1407 min: 432 cycles q1: 432 cycles median: 435 cycles q3: 435 cycles max: 1407 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_x86-64_nnacl_newlib_static= {435, 3} count Apparent clock speed: 2736 MHz TestThreadCreateAndJoin: Measuring real time: 65.876 usec (6.58757e-05 sec) per iteration: 0.00658757 sec for 100 iterations 63.593 usec (6.35926e-05 sec) per iteration: 0.0965335 sec for 1518 iterations 63.401 usec (6.34012e-05 sec) per iteration: 0.096243 sec for 1518 iterations 63.029 usec (6.30287e-05 sec) per iteration: 0.0956776 sec for 1518 iterations 62.986 usec (6.29861e-05 sec) per iteration: 0.095613 sec for 1518 iterations 64.908 usec (6.49079e-05 sec) per iteration: 0.0985302 sec for 1518 iterations mean: 63.583307 usec stddev: 0.700287 usec relative stddev: 1.10% RESULT TestThreadCreateAndJoin: gn_x86-64_nnacl_newlib_static= {63.583307, 0.700287} us Measuring clock cycles: first runs (cycles): 235743 221550 281394 256266 243192 193074 181599 185646 171612 170169 ... slowest runs (cycles): ... 172065 172857 181599 185646 193074 221550 235743 243192 256266 281394 min: 164700 cycles q1: 166641 cycles median: 167751 cycles q3: 169416 cycles max: 281394 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_x86-64_nnacl_newlib_static= {167751, 2775} count Apparent clock speed: 2638 MHz TestThreadWakeup: Measuring real time: 32.722 usec (3.27224e-05 sec) per iteration: 0.00327224 sec for 100 iterations 31.622 usec (3.16218e-05 sec) per iteration: 0.0966362 sec for 3056 iterations 30.736 usec (3.07365e-05 sec) per iteration: 0.0939306 sec for 3056 iterations 30.772 usec (3.07721e-05 sec) per iteration: 0.0940396 sec for 3056 iterations 30.718 usec (3.07179e-05 sec) per iteration: 0.0938739 sec for 3056 iterations 31.396 usec (3.13957e-05 sec) per iteration: 0.0959453 sec for 3056 iterations mean: 31.048797 usec stddev: 0.382693 usec relative stddev: 1.23% RESULT TestThreadWakeup: gn_x86-64_nnacl_newlib_static= {31.048797, 0.382693} us Measuring clock cycles: first runs (cycles): 89949 100950 96243 81753 83712 132867 91515 88710 93183 80025 ... slowest runs (cycles): ... 88122 88710 89949 91113 91515 93183 96243 97356 100950 132867 min: 68430 cycles q1: 82746 cycles median: 83268 cycles q3: 84348 cycles max: 132867 cycles RESULT TestThreadWakeup_CycleCount: gn_x86-64_nnacl_newlib_static= {83268, 1602} count Apparent clock speed: 2682 MHz TestCatchingFault: Measuring real time: 32.312 usec (3.23116e-05 sec) per iteration: 0.00323116 sec for 100 iterations 31.133 usec (3.11334e-05 sec) per iteration: 0.0963267 sec for 3094 iterations 30.734 usec (3.07344e-05 sec) per iteration: 0.0950921 sec for 3094 iterations 30.713 usec (3.07135e-05 sec) per iteration: 0.0950275 sec for 3094 iterations 30.553 usec (3.05526e-05 sec) per iteration: 0.0945298 sec for 3094 iterations 30.647 usec (3.06467e-05 sec) per iteration: 0.094821 sec for 3094 iterations mean: 30.756114 usec stddev: 0.199000 usec relative stddev: 0.65% RESULT TestCatchingFault: gn_x86-64_nnacl_newlib_static= {30.756114, 0.199000} us Measuring clock cycles: first runs (cycles): 103521 85737 83952 103311 128100 156225 166227 109236 112698 100473 ... slowest runs (cycles): ... 96771 100473 103311 103521 104922 109236 112698 128100 156225 166227 min: 80805 cycles q1: 81822 cycles median: 82239 cycles q3: 83004 cycles max: 166227 cycles RESULT TestCatchingFault_CycleCount: gn_x86-64_nnacl_newlib_static= {82239, 1182} count Apparent clock speed: 2674 MHz TestThreadCreateAndJoinAfterSettingFaultHandler: Measuring real time: 66.484 usec (6.64844e-05 sec) per iteration: 0.00664844 sec for 100 iterations 62.947 usec (6.29472e-05 sec) per iteration: 0.0946726 sec for 1504 iterations 63.324 usec (6.33244e-05 sec) per iteration: 0.0952399 sec for 1504 iterations 64.369 usec (6.43686e-05 sec) per iteration: 0.0968103 sec for 1504 iterations 64.612 usec (6.46122e-05 sec) per iteration: 0.0971768 sec for 1504 iterations 63.589 usec (6.35893e-05 sec) per iteration: 0.0956382 sec for 1504 iterations mean: 63.768342 usec stddev: 0.628628 usec relative stddev: 0.99% RESULT TestThreadCreateAndJoinAfterSettingFaultHandler: gn_x86-64_nnacl_newlib_static= {63.768342, 0.628628} us Measuring clock cycles: first runs (cycles): 169338 178128 199779 178341 227424 216006 230388 226488 224640 225975 ... slowest runs (cycles): ... 219681 220143 220164 220413 221610 224640 225975 226488 227424 230388 min: 169338 cycles q1: 214479 cycles median: 215718 cycles q3: 217764 cycles max: 230388 cycles RESULT TestThreadCreateAndJoinAfterSettingFaultHandler_CycleCount: gn_x86-64_nnacl_newlib_static= {215718, 3285} count Apparent clock speed: 3383 MHz [ OK ] nacl_newlib.run_performance_test (6270 ms) /b/s/w/ir/cache/vpython/46fcd9/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 (1520 ms) /b/s/w/ir/cache/vpython/46fcd9/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 (780 ms) /b/s/w/ir/cache/vpython/46fcd9/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.002 usec (2e-09 sec) per iteration: 2e-06 sec for 1000 iterations 0.002 usec (2e-09 sec) per iteration: 2e-05 sec for 10000 iterations 0.002 usec (1.99654e-09 sec) per iteration: 0.099827 sec for 49999999 iterations 0.002 usec (1.98658e-09 sec) per iteration: 0.099329 sec for 49999999 iterations 0.002 usec (1.99764e-09 sec) per iteration: 0.099882 sec for 49999999 iterations 0.002 usec (1.99912e-09 sec) per iteration: 0.099956 sec for 49999999 iterations 0.002 usec (1.9976e-09 sec) per iteration: 0.09988 sec for 49999999 iterations mean: 0.001995 usec stddev: 0.000005 usec relative stddev: 0.23% RESULT TestNull: gn_trusted_mac_x86-64= {0.001995, 0.000005} us Measuring clock cycles: first runs (cycles): 234 30 18 21 18 21 18 30 27 30 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 30 234 min: 18 cycles q1: 18 cycles median: 21 cycles q3: 30 cycles max: 234 cycles RESULT TestNull_CycleCount: gn_trusted_mac_x86-64= {21, 12} count Apparent clock speed: 10524 MHz TestHostSyscall: Measuring real time: 1.140 usec (1.14e-06 sec) per iteration: 0.000114 sec for 100 iterations 0.987 usec (9.87357e-07 sec) per iteration: 0.08661 sec for 87719 iterations 0.972 usec (9.71785e-07 sec) per iteration: 0.085244 sec for 87719 iterations 0.983 usec (9.82946e-07 sec) per iteration: 0.086223 sec for 87719 iterations 0.962 usec (9.62471e-07 sec) per iteration: 0.084427 sec for 87719 iterations 0.976 usec (9.75672e-07 sec) per iteration: 0.085585 sec for 87719 iterations mean: 0.976046 usec stddev: 0.008696 usec relative stddev: 0.89% RESULT TestHostSyscall: gn_trusted_mac_x86-64= {0.976046, 0.008696} us Measuring clock cycles: first runs (cycles): 3006 2715 2634 2676 2679 2679 2676 2676 2679 2670 ... slowest runs (cycles): ... 2679 2679 2679 2679 2679 2679 2679 2715 3006 40809 min: 2424 cycles q1: 2433 cycles median: 2547 cycles q3: 2676 cycles max: 40809 cycles RESULT TestHostSyscall_CycleCount: gn_trusted_mac_x86-64= {2547, 243} count Apparent clock speed: 2610 MHz TestSetjmpLongjmp: Measuring real time: 6.150 usec (6.15e-06 sec) per iteration: 0.000615 sec for 100 iterations 4.865 usec (4.86531e-06 sec) per iteration: 0.07911 sec for 16260 iterations 4.773 usec (4.77349e-06 sec) per iteration: 0.077617 sec for 16260 iterations 4.786 usec (4.78598e-06 sec) per iteration: 0.07782 sec for 16260 iterations 4.765 usec (4.76476e-06 sec) per iteration: 0.077475 sec for 16260 iterations 4.725 usec (4.72485e-06 sec) per iteration: 0.076826 sec for 16260 iterations mean: 4.782878 usec stddev: 0.046020 usec relative stddev: 0.96% RESULT TestSetjmpLongjmp: gn_trusted_mac_x86-64= {4.782878, 0.046020} us Measuring clock cycles: first runs (cycles): 14265 13119 13071 13071 13074 13059 13065 13086 13077 13074 ... slowest runs (cycles): ... 13167 13170 13203 13206 13209 13227 13236 13245 13272 14265 min: 13059 cycles q1: 13071 cycles median: 13086 cycles q3: 13107 cycles max: 14265 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_trusted_mac_x86-64= {13086, 36} count Apparent clock speed: 2736 MHz TestClockGetTime: Measuring real time: 0.070 usec (7e-08 sec) per iteration: 7e-06 sec for 100 iterations 0.076 usec (7.6e-08 sec) per iteration: 7.6e-05 sec for 1000 iterations 0.076 usec (7.63458e-08 sec) per iteration: 0.100455 sec for 1315789 iterations 0.076 usec (7.57089e-08 sec) per iteration: 0.099617 sec for 1315789 iterations 0.075 usec (7.50097e-08 sec) per iteration: 0.098697 sec for 1315789 iterations 0.075 usec (7.47673e-08 sec) per iteration: 0.098378 sec for 1315789 iterations 0.075 usec (7.48372e-08 sec) per iteration: 0.09847 sec for 1315789 iterations mean: 0.075334 usec stddev: 0.000606 usec relative stddev: 0.80% RESULT TestClockGetTime: gn_trusted_mac_x86-64= {0.075334, 0.000606} us Measuring clock cycles: first runs (cycles): 1443 252 213 213 213 216 213 210 216 210 ... slowest runs (cycles): ... 216 216 216 216 216 216 216 234 252 1443 min: 201 cycles q1: 210 cycles median: 213 cycles q3: 216 cycles max: 1443 cycles RESULT TestClockGetTime_CycleCount: gn_trusted_mac_x86-64= {213, 6} count Apparent clock speed: 2827 MHz TestMmapAnonymous: Measuring real time: 3.410 usec (3.41e-06 sec) per iteration: 0.000341 sec for 100 iterations 3.079 usec (3.07857e-06 sec) per iteration: 0.090279 sec for 29325 iterations 3.079 usec (3.07939e-06 sec) per iteration: 0.090303 sec for 29325 iterations 3.073 usec (3.07321e-06 sec) per iteration: 0.090122 sec for 29325 iterations 3.041 usec (3.04143e-06 sec) per iteration: 0.08919 sec for 29325 iterations 3.064 usec (3.06408e-06 sec) per iteration: 0.089854 sec for 29325 iterations mean: 3.067335 usec stddev: 0.014054 usec relative stddev: 0.46% RESULT TestMmapAnonymous: gn_trusted_mac_x86-64= {3.067335, 0.014054} us Measuring clock cycles: first runs (cycles): 11178 7764 7611 7506 7497 7602 7539 7485 7545 7539 ... slowest runs (cycles): ... 8301 8313 8319 8358 8400 8448 11178 45102 46905 47259 min: 7461 cycles q1: 7539 cycles median: 7956 cycles q3: 8265 cycles max: 47259 cycles RESULT TestMmapAnonymous_CycleCount: gn_trusted_mac_x86-64= {7956, 726} count Apparent clock speed: 2594 MHz TestAtomicIncrement: Measuring real time: 0.010 usec (1e-08 sec) per iteration: 1e-06 sec for 100 iterations 0.007 usec (7e-09 sec) per iteration: 7e-06 sec for 1000 iterations 0.007 usec (7.3e-09 sec) per iteration: 7.3e-05 sec for 10000 iterations 0.007 usec (7.21985e-09 sec) per iteration: 0.098902 sec for 13698630 iterations 0.007 usec (7.01311e-09 sec) per iteration: 0.09607 sec for 13698630 iterations 0.007 usec (7.28562e-09 sec) per iteration: 0.099803 sec for 13698630 iterations 0.007 usec (7.29839e-09 sec) per iteration: 0.099978 sec for 13698630 iterations 0.007 usec (7.24262e-09 sec) per iteration: 0.099214 sec for 13698630 iterations mean: 0.007212 usec stddev: 0.000103 usec relative stddev: 1.43% RESULT TestAtomicIncrement: gn_trusted_mac_x86-64= {0.007212, 0.000103} us Measuring clock cycles: first runs (cycles): 273 54 51 54 51 54 48 48 39 48 ... slowest runs (cycles): ... 48 48 48 51 51 54 54 54 63 273 min: 39 cycles q1: 39 cycles median: 48 cycles q3: 48 cycles max: 273 cycles RESULT TestAtomicIncrement_CycleCount: gn_trusted_mac_x86-64= {48, 9} count Apparent clock speed: 6656 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.65629e-08 sec) per iteration: 0.012649 sec for 476190 iterations 0.027 usec (2.65293e-08 sec) per iteration: 0.012633 sec for 476190 iterations 0.027 usec (2.6523e-08 sec) per iteration: 0.01263 sec for 476190 iterations 0.027 usec (2.65566e-08 sec) per iteration: 0.012646 sec for 476190 iterations 0.027 usec (2.65545e-08 sec) per iteration: 0.012645 sec for 476190 iterations mean: 0.026545 usec stddev: 0.000016 usec relative stddev: 0.06% RESULT TestUncontendedMutexLock: gn_trusted_mac_x86-64= {0.026545, 0.000016} us Measuring clock cycles: first runs (cycles): 420 105 84 84 93 96 96 93 84 87 ... slowest runs (cycles): ... 96 96 96 96 96 96 96 105 114 420 min: 84 cycles q1: 87 cycles median: 93 cycles q3: 96 cycles max: 420 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_trusted_mac_x86-64= {93, 9} count Apparent clock speed: 3503 MHz TestCondvarSignalNoOp: Measuring real time: 0.110 usec (1.1e-07 sec) per iteration: 1.1e-05 sec for 100 iterations 0.022 usec (2.19582e-08 sec) per iteration: 0.019962 sec for 909090 iterations 0.022 usec (2.18691e-08 sec) per iteration: 0.019881 sec for 909090 iterations 0.021 usec (2.1021e-08 sec) per iteration: 0.01911 sec for 909090 iterations 0.021 usec (2.14995e-08 sec) per iteration: 0.019545 sec for 909090 iterations 0.021 usec (2.14467e-08 sec) per iteration: 0.019497 sec for 909090 iterations mean: 0.021559 usec stddev: 0.000335 usec relative stddev: 1.55% RESULT TestCondvarSignalNoOp: gn_trusted_mac_x86-64= {0.021559, 0.000335} us Measuring clock cycles: first runs (cycles): 666 81 60 69 60 60 60 60 69 60 ... slowest runs (cycles): ... 69 69 69 69 69 69 69 75 81 666 min: 60 cycles q1: 60 cycles median: 60 cycles q3: 60 cycles max: 666 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_trusted_mac_x86-64= {60, 0} count Apparent clock speed: 2783 MHz TestThreadCreateAndJoin: Measuring real time: 82.410 usec (8.241e-05 sec) per iteration: 0.008241 sec for 100 iterations 79.291 usec (7.9291e-05 sec) per iteration: 0.09618 sec for 1213 iterations 79.968 usec (7.99678e-05 sec) per iteration: 0.097001 sec for 1213 iterations 78.491 usec (7.84905e-05 sec) per iteration: 0.095209 sec for 1213 iterations 79.580 usec (7.95796e-05 sec) per iteration: 0.09653 sec for 1213 iterations 77.557 usec (7.75573e-05 sec) per iteration: 0.094077 sec for 1213 iterations mean: 78.977246 usec stddev: 0.859730 usec relative stddev: 1.09% RESULT TestThreadCreateAndJoin: gn_trusted_mac_x86-64= {78.977246, 0.859730} us Measuring clock cycles: first runs (cycles): 151767 280089 309918 229518 209463 159315 149268 193713 165456 261120 ... slowest runs (cycles): ... 250698 250980 254565 257133 261120 263037 267363 280089 289263 309918 min: 128862 cycles q1: 149268 cycles median: 235050 cycles q3: 244104 cycles max: 309918 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_trusted_mac_x86-64= {235050, 94836} count Apparent clock speed: 2976 MHz TestThreadWakeup: Measuring real time: 21.400 usec (2.14e-05 sec) per iteration: 0.00214 sec for 100 iterations 20.731 usec (2.07312e-05 sec) per iteration: 0.096856 sec for 4672 iterations 21.430 usec (2.14298e-05 sec) per iteration: 0.10012 sec for 4672 iterations 20.750 usec (2.07504e-05 sec) per iteration: 0.096946 sec for 4672 iterations 20.788 usec (2.07879e-05 sec) per iteration: 0.097121 sec for 4672 iterations 20.837 usec (2.08367e-05 sec) per iteration: 0.097349 sec for 4672 iterations mean: 20.907192 usec stddev: 0.263772 usec relative stddev: 1.26% RESULT TestThreadWakeup: gn_trusted_mac_x86-64= {20.907192, 0.263772} us Measuring clock cycles: first runs (cycles): 66783 54375 52563 53556 52875 93036 72783 97578 51309 61257 ... slowest runs (cycles): ... 65478 66783 66819 67581 69327 72783 93036 97578 141225 144915 min: 51309 cycles q1: 52368 cycles median: 53031 cycles q3: 57726 cycles max: 144915 cycles RESULT TestThreadWakeup_CycleCount: gn_trusted_mac_x86-64= {53031, 5358} count Apparent clock speed: 2536 MHz WARNING: should have taken less than 2.000000 secs [ OK ] nacl_newlib.run_trusted_performance_test (3980 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