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

Running command: /b/s/w/ir/cache/vpython/7c7ecd/bin/python scons.py --verbose -k -j1 --mode=nacl,dbg-host platform=x86-64 --clang large_tests 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,dbg-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 = 1547621684, usec = 967389 } Tue Jan 15 22:54:44 2019 ====================================================================== The following environments have been configured ====================================================================== NACL_BUILD_FAMILY: UNTRUSTED BUILD_TYPE: nacl TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/obj BUILD_TYPE_DESCRIPTION: NaCl module build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang ASPPCOM: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_GNU_SOURCE=1 -D_POSIX_C_SOURCE=199506 -D_XOPEN_SOURCE=600 -DDYNAMIC_ANNOTATIONS_ENABLED=1 -DDYNAMIC_ANNOTATIONS_PREFIX=NACL_ -DNACL_BUILD_ARCH=x86 -DNACL_BUILD_SUBARCH=64 -I/b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl-x86-64/include -I/b/s/w/ir/kitchen-workdir -c -o UNKNOWN COMPILER NACL_BUILD_FAMILY: TRUSTED BUILD_TYPE: dbg-mac TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj BUILD_TYPE_DESCRIPTION: MacOS dbg build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/third_party/llvm-build/Release+Asserts/bin/clang ASPPCOM: /b/s/w/ir/kitchen-workdir/third_party/llvm-build/Release+Asserts/bin/clang -isysroot /b/s/w/ir/cache/osx_sdk/XCode.app/Contents/Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX10.13.sdk -mmacosx-version-min=10.6 -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_DEBUG -I/b/s/w/ir/kitchen-workdir -c -o UNKNOWN COMPILER NACL_BUILD_FAMILY: UNTRUSTED_IRT BUILD_TYPE: nacl_irt TARGET_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64 OBJ_ROOT: /b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64/obj BUILD_TYPE_DESCRIPTION: NaCl IRT build BUILD_OS: BUILD_ARCHITECTURE: x86 BUILD_SUBARCH: 64 TARGET_OS: TARGET_ARCHITECTURE: x86 TARGET_SUBARCH: 64 CC: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang ASPPCOM: /b/s/w/ir/kitchen-workdir/native_client/toolchain/mac_x86/pnacl_newlib_raw/bin/x86_64-nacl-clang -m64 -D__STDC_LIMIT_MACROS=1 -D__STDC_FORMAT_MACROS=1 -D_GNU_SOURCE=1 -D_POSIX_C_SOURCE=199506 -D_XOPEN_SOURCE=600 -DDYNAMIC_ANNOTATIONS_ENABLED=1 -DDYNAMIC_ANNOTATIONS_PREFIX=NACL_ -DNACL_BUILD_ARCH=x86 -DNACL_BUILD_SUBARCH=64 -I/b/s/w/ir/kitchen-workdir/native_client/scons-out/nacl_irt-x86-64/include -I/b/s/w/ir/kitchen-workdir -I/b/s/w/ir/kitchen-workdir/native_client/src/untrusted/pthread -c -o UNKNOWN COMPILER *** BROKEN run_ncval_annotate_test *** BROKEN run_gdb_invalid_memory_test *** BROKEN run_nanosleep_test *** BROKEN run_timefuncs_test *** BROKEN run_raw_timefuncs_test *** BROKEN run_main_thread_pthread_exit_test2 *** BROKEN run_overflowinline_test *** BROKEN run_stack_frame_noopt_frame_test *** BROKEN run_stack_frame_noopt_noframe_test *** BROKEN run_stack_frame_opt_frame_test *** BROKEN run_stack_frame_opt_noframe_test *** BROKEN run_vla_test *** BROKEN run_nacl_sync_cond_test SKIPPING test text_overlaps_rodata SKIPPING test text_overlaps_data There are 13 broken tests. ====================================================================== B U I L D - O U T P U T: ====================================================================== scons: done reading SConscript files. scons: Building targets ... /b/s/w/ir/cache/vpython/7c7ecd/bin/python tools/command_tester.py --name nacl_newlib.run_benchmark_test --time_warning 10 --time_error 100 --perf_env_description 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 [39909,2906624896:09:46:51.098099] Native Client module will be loaded at base address 0x00002b6400000000 Running suite of 1 benchmarks: Running Benchmark: Life (SIMD version)... RESULT BenchmarkLife: gn_x86-64_nnacl_newlib_static= {0.079820, 0.001090} seconds --------------------------------------------------------------- Done running benchmark suite. [ OK ] nacl_newlib.run_benchmark_test (990 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 (66279 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/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 [39915,2906624896:09:47:05.298859] Native Client module will be loaded at base address 0x00006e9500000000 TestNull: Measuring real time: 0.014 usec (1.392e-08 sec) per iteration: 1.392e-06 sec for 100 iterations 0.002 usec (2.424e-09 sec) per iteration: 2.424e-06 sec for 1000 iterations 0.002 usec (2.0412e-09 sec) per iteration: 2.0412e-05 sec for 10000 iterations 0.002 usec (2.1879e-09 sec) per iteration: 0.107187 sec for 48990789 iterations 0.002 usec (1.97639e-09 sec) per iteration: 0.0968248 sec for 48990789 iterations 0.002 usec (1.97237e-09 sec) per iteration: 0.096628 sec for 48990789 iterations 0.002 usec (1.96179e-09 sec) per iteration: 0.0961096 sec for 48990789 iterations 0.002 usec (2.00771e-09 sec) per iteration: 0.0983594 sec for 48990789 iterations mean: 0.002021 usec stddev: 0.000085 usec relative stddev: 4.19% RESULT TestNull: gn_x86-64_nnacl_newlib_static= {0.002021, 0.000085} us Measuring clock cycles: first runs (cycles): 258 45 21 21 21 18 21 18 30 27 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 45 258 min: 18 cycles q1: 18 cycles median: 21 cycles q3: 27 cycles max: 258 cycles RESULT TestNull_CycleCount: gn_x86-64_nnacl_newlib_static= {21, 9} count Apparent clock speed: 10390 MHz TestNaClSyscall: Measuring real time: 0.220 usec (2.2011e-07 sec) per iteration: 2.2011e-05 sec for 100 iterations 0.201 usec (2.0093e-07 sec) per iteration: 0.091286 sec for 454318 iterations 0.203 usec (2.02777e-07 sec) per iteration: 0.0921254 sec for 454318 iterations 0.202 usec (2.01624e-07 sec) per iteration: 0.0916016 sec for 454318 iterations 0.206 usec (2.05713e-07 sec) per iteration: 0.0934593 sec for 454318 iterations 0.198 usec (1.98266e-07 sec) per iteration: 0.0900758 sec for 454318 iterations mean: 0.201862 usec stddev: 0.002430 usec relative stddev: 1.20% RESULT TestNaClSyscall: gn_x86-64_nnacl_newlib_static= {0.201862, 0.002430} us Measuring clock cycles: first runs (cycles): 1077 495 492 492 492 501 492 495 492 489 ... slowest runs (cycles): ... 501 504 504 504 504 504 504 504 504 1077 min: 486 cycles q1: 492 cycles median: 492 cycles q3: 495 cycles max: 1077 cycles RESULT TestNaClSyscall_CycleCount: gn_x86-64_nnacl_newlib_static= {492, 3} count Apparent clock speed: 2437 MHz TestSetjmpLongjmp: Measuring real time: 0.018 usec (1.794e-08 sec) per iteration: 1.794e-06 sec for 100 iterations 0.013 usec (1.255e-08 sec) per iteration: 1.255e-05 sec for 1000 iterations 0.012 usec (1.20203e-08 sec) per iteration: 0.0957792 sec for 7968127 iterations 0.012 usec (1.21105e-08 sec) per iteration: 0.0964982 sec for 7968127 iterations 0.012 usec (1.19702e-08 sec) per iteration: 0.0953802 sec for 7968127 iterations 0.012 usec (1.19223e-08 sec) per iteration: 0.0949982 sec for 7968127 iterations 0.012 usec (1.19731e-08 sec) per iteration: 0.095403 sec for 7968127 iterations mean: 0.011999 usec stddev: 0.000064 usec relative stddev: 0.53% RESULT TestSetjmpLongjmp: gn_x86-64_nnacl_newlib_static= {0.011999, 0.000064} us Measuring clock cycles: first runs (cycles): 417 33 33 33 36 24 24 24 33 33 ... slowest runs (cycles): ... 33 33 33 33 33 33 33 33 36 417 min: 21 cycles q1: 24 cycles median: 30 cycles q3: 33 cycles max: 417 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_x86-64_nnacl_newlib_static= {30, 9} count Apparent clock speed: 2500 MHz TestClockGetTime: Measuring real time: 0.330 usec (3.301e-07 sec) per iteration: 3.301e-05 sec for 100 iterations 0.319 usec (3.18935e-07 sec) per iteration: 0.0966176 sec for 302938 iterations 0.317 usec (3.17071e-07 sec) per iteration: 0.0960529 sec for 302938 iterations 0.323 usec (3.23042e-07 sec) per iteration: 0.0978616 sec for 302938 iterations 0.320 usec (3.19844e-07 sec) per iteration: 0.0968928 sec for 302938 iterations 0.314 usec (3.13594e-07 sec) per iteration: 0.0949996 sec for 302938 iterations mean: 0.318497 usec stddev: 0.003122 usec relative stddev: 0.98% RESULT TestClockGetTime: gn_x86-64_nnacl_newlib_static= {0.318497, 0.003122} us Measuring clock cycles: first runs (cycles): 2553 927 930 864 879 864 885 864 867 867 ... slowest runs (cycles): ... 927 930 936 939 942 948 951 966 975 2553 min: 861 cycles q1: 867 cycles median: 870 cycles q3: 876 cycles max: 2553 cycles RESULT TestClockGetTime_CycleCount: gn_x86-64_nnacl_newlib_static= {870, 9} count Apparent clock speed: 2732 MHz TestTlsVariable: Measuring real time: 0.011 usec (1.139e-08 sec) per iteration: 1.139e-06 sec for 100 iterations 0.006 usec (6.422e-09 sec) per iteration: 6.422e-06 sec for 1000 iterations 0.006 usec (6.0437e-09 sec) per iteration: 6.0437e-05 sec for 10000 iterations 0.006 usec (6.07661e-09 sec) per iteration: 0.100545 sec for 16546155 iterations 0.006 usec (5.8878e-09 sec) per iteration: 0.0974204 sec for 16546155 iterations 0.006 usec (6.09009e-09 sec) per iteration: 0.100768 sec for 16546155 iterations 0.006 usec (6.03592e-09 sec) per iteration: 0.0998713 sec for 16546155 iterations 0.006 usec (6.08347e-09 sec) per iteration: 0.100658 sec for 16546155 iterations mean: 0.006035 usec stddev: 0.000076 usec relative stddev: 1.26% RESULT TestTlsVariable: gn_x86-64_nnacl_newlib_static= {0.006035, 0.000076} us Measuring clock cycles: first runs (cycles): 300 75 30 21 21 21 18 21 18 30 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 75 300 min: 18 cycles q1: 18 cycles median: 21 cycles q3: 30 cycles max: 300 cycles RESULT TestTlsVariable_CycleCount: gn_x86-64_nnacl_newlib_static= {21, 12} count Apparent clock speed: 3480 MHz TestMmapAnonymous: Measuring real time: 9.849 usec (9.8492e-06 sec) per iteration: 0.00098492 sec for 100 iterations 9.576 usec (9.57591e-06 sec) per iteration: 0.0972243 sec for 10153 iterations 9.588 usec (9.58761e-06 sec) per iteration: 0.097343 sec for 10153 iterations 9.592 usec (9.59238e-06 sec) per iteration: 0.0973914 sec for 10153 iterations 10.446 usec (1.04462e-05 sec) per iteration: 0.10606 sec for 10153 iterations 9.755 usec (9.75479e-06 sec) per iteration: 0.0990404 sec for 10153 iterations mean: 9.791368 usec stddev: 0.333951 usec relative stddev: 3.41% RESULT TestMmapAnonymous: gn_x86-64_nnacl_newlib_static= {9.791368, 0.333951} us Measuring clock cycles: first runs (cycles): 39489 27909 27171 26859 26478 26484 26676 26676 26940 26928 ... slowest runs (cycles): ... 27045 27057 27114 27171 27279 27318 27579 27909 39489 54330 min: 26352 cycles q1: 26649 cycles median: 26781 cycles q3: 26937 cycles max: 54330 cycles RESULT TestMmapAnonymous_CycleCount: gn_x86-64_nnacl_newlib_static= {26781, 288} count Apparent clock speed: 2735 MHz TestAtomicIncrement: Measuring real time: 0.019 usec (1.859e-08 sec) per iteration: 1.859e-06 sec for 100 iterations 0.010 usec (1.0119e-08 sec) per iteration: 1.0119e-05 sec for 1000 iterations 0.010 usec (9.6896e-09 sec) per iteration: 0.0957565 sec for 9882399 iterations 0.010 usec (9.66899e-09 sec) per iteration: 0.0955528 sec for 9882399 iterations 0.009 usec (9.45186e-09 sec) per iteration: 0.093407 sec for 9882399 iterations 0.010 usec (9.72461e-09 sec) per iteration: 0.0961024 sec for 9882399 iterations 0.010 usec (9.88921e-09 sec) per iteration: 0.0977291 sec for 9882399 iterations mean: 0.009685 usec stddev: 0.000140 usec relative stddev: 1.44% RESULT TestAtomicIncrement: gn_x86-64_nnacl_newlib_static= {0.009685, 0.000140} us Measuring clock cycles: first runs (cycles): 282 39 48 51 51 51 51 51 51 51 ... slowest runs (cycles): ... 51 51 51 51 51 51 51 51 51 282 min: 39 cycles q1: 51 cycles median: 51 cycles q3: 51 cycles max: 282 cycles RESULT TestAtomicIncrement_CycleCount: gn_x86-64_nnacl_newlib_static= {51, 0} count Apparent clock speed: 5266 MHz TestUncontendedMutexLock: Measuring real time: 0.030 usec (2.965e-08 sec) per iteration: 2.965e-06 sec for 100 iterations 0.023 usec (2.342e-08 sec) per iteration: 2.342e-05 sec for 1000 iterations 0.023 usec (2.28755e-08 sec) per iteration: 0.0976751 sec for 4269854 iterations 0.023 usec (2.26548e-08 sec) per iteration: 0.0967326 sec for 4269854 iterations 0.023 usec (2.27615e-08 sec) per iteration: 0.0971882 sec for 4269854 iterations 0.023 usec (2.25904e-08 sec) per iteration: 0.0964577 sec for 4269854 iterations 0.023 usec (2.29772e-08 sec) per iteration: 0.0981094 sec for 4269854 iterations mean: 0.022772 usec stddev: 0.000141 usec relative stddev: 0.62% RESULT TestUncontendedMutexLock: gn_x86-64_nnacl_newlib_static= {0.022772, 0.000141} us Measuring clock cycles: first runs (cycles): 471 108 90 87 90 87 90 87 90 87 ... slowest runs (cycles): ... 90 90 90 90 90 90 90 93 108 471 min: 78 cycles q1: 81 cycles median: 90 cycles q3: 90 cycles max: 471 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_x86-64_nnacl_newlib_static= {90, 9} count Apparent clock speed: 3952 MHz TestCondvarSignalNoOp: Measuring real time: 0.362 usec (3.6191e-07 sec) per iteration: 3.6191e-05 sec for 100 iterations 0.244 usec (2.43715e-07 sec) per iteration: 0.0673413 sec for 276311 iterations 0.246 usec (2.4635e-07 sec) per iteration: 0.0680693 sec for 276311 iterations 0.240 usec (2.4018e-07 sec) per iteration: 0.0663643 sec for 276311 iterations 0.236 usec (2.35557e-07 sec) per iteration: 0.0650869 sec for 276311 iterations 0.239 usec (2.38665e-07 sec) per iteration: 0.0659457 sec for 276311 iterations mean: 0.240893 usec stddev: 0.003787 usec relative stddev: 1.57% RESULT TestCondvarSignalNoOp: gn_x86-64_nnacl_newlib_static= {0.240893, 0.003787} us Measuring clock cycles: first runs (cycles): 1923 654 645 714 654 648 651 663 651 645 ... slowest runs (cycles): ... 663 663 666 666 666 666 711 714 723 1923 min: 636 cycles q1: 648 cycles median: 648 cycles q3: 651 cycles max: 1923 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_x86-64_nnacl_newlib_static= {648, 3} count Apparent clock speed: 2690 MHz TestThreadCreateAndJoin: Measuring real time: 95.452 usec (9.54522e-05 sec) per iteration: 0.00954522 sec for 100 iterations 102.857 usec (0.000102857 sec) per iteration: 0.107692 sec for 1047 iterations 97.424 usec (9.74242e-05 sec) per iteration: 0.102003 sec for 1047 iterations 94.410 usec (9.44102e-05 sec) per iteration: 0.0988475 sec for 1047 iterations 95.229 usec (9.52293e-05 sec) per iteration: 0.0997051 sec for 1047 iterations 92.328 usec (9.23281e-05 sec) per iteration: 0.0966675 sec for 1047 iterations mean: 96.449822 usec stddev: 3.595646 usec relative stddev: 3.73% RESULT TestThreadCreateAndJoin: gn_x86-64_nnacl_newlib_static= {96.449822, 3.595646} us Measuring clock cycles: first runs (cycles): 262269 260568 299988 255117 232281 247854 241557 241725 241659 246684 ... slowest runs (cycles): ... 262548 262596 263004 263166 264624 265467 277890 277929 280707 299988 min: 228303 cycles q1: 244791 cycles median: 251508 cycles q3: 258765 cycles max: 299988 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_x86-64_nnacl_newlib_static= {251508, 13974} count Apparent clock speed: 2608 MHz TestThreadWakeup: Measuring real time: 30.273 usec (3.02731e-05 sec) per iteration: 0.00302731 sec for 100 iterations 31.142 usec (3.11415e-05 sec) per iteration: 0.10286 sec for 3303 iterations 32.522 usec (3.25223e-05 sec) per iteration: 0.107421 sec for 3303 iterations 31.686 usec (3.16861e-05 sec) per iteration: 0.104659 sec for 3303 iterations 31.581 usec (3.15809e-05 sec) per iteration: 0.104312 sec for 3303 iterations 31.872 usec (3.18723e-05 sec) per iteration: 0.105274 sec for 3303 iterations mean: 31.760638 usec stddev: 0.450274 usec relative stddev: 1.42% RESULT TestThreadWakeup: gn_x86-64_nnacl_newlib_static= {31.760638, 0.450274} us Measuring clock cycles: first runs (cycles): 87882 90765 95283 147279 83595 100395 82761 96882 94755 114678 ... slowest runs (cycles): ... 103761 104475 107670 107883 114678 115842 125538 138108 146445 147279 min: 73893 cycles q1: 82944 cycles median: 84153 cycles q3: 86229 cycles max: 147279 cycles RESULT TestThreadWakeup_CycleCount: gn_x86-64_nnacl_newlib_static= {84153, 3285} count Apparent clock speed: 2650 MHz TestCatchingFault: Measuring real time: 33.571 usec (3.35711e-05 sec) per iteration: 0.00335711 sec for 100 iterations 31.668 usec (3.16676e-05 sec) per iteration: 0.094306 sec for 2978 iterations 31.324 usec (3.13244e-05 sec) per iteration: 0.093284 sec for 2978 iterations 31.276 usec (3.12763e-05 sec) per iteration: 0.0931407 sec for 2978 iterations 31.500 usec (3.15004e-05 sec) per iteration: 0.093808 sec for 2978 iterations 30.951 usec (3.09511e-05 sec) per iteration: 0.0921725 sec for 2978 iterations mean: 31.343943 usec stddev: 0.240187 usec relative stddev: 0.77% RESULT TestCatchingFault: gn_x86-64_nnacl_newlib_static= {31.343943, 0.240187} us Measuring clock cycles: first runs (cycles): 104763 97434 137565 99132 87666 103242 146361 112617 99768 107157 ... slowest runs (cycles): ... 104763 105093 105933 107157 108660 112617 115365 137565 145659 146361 min: 81159 cycles q1: 83340 cycles median: 83937 cycles q3: 84912 cycles max: 146361 cycles RESULT TestCatchingFault_CycleCount: gn_x86-64_nnacl_newlib_static= {83937, 1572} count Apparent clock speed: 2678 MHz TestThreadCreateAndJoinAfterSettingFaultHandler: Measuring real time: 93.315 usec (9.33153e-05 sec) per iteration: 0.00933153 sec for 100 iterations 92.452 usec (9.24516e-05 sec) per iteration: 0.0990157 sec for 1071 iterations 93.678 usec (9.36782e-05 sec) per iteration: 0.100329 sec for 1071 iterations 93.423 usec (9.34228e-05 sec) per iteration: 0.100056 sec for 1071 iterations 92.018 usec (9.20177e-05 sec) per iteration: 0.098551 sec for 1071 iterations 91.408 usec (9.14078e-05 sec) per iteration: 0.0978978 sec for 1071 iterations mean: 92.595653 usec stddev: 0.851105 usec relative stddev: 0.92% RESULT TestThreadCreateAndJoinAfterSettingFaultHandler: gn_x86-64_nnacl_newlib_static= {92.595653, 0.851105} us Measuring clock cycles: first runs (cycles): 229647 243015 347325 250317 266313 256638 256038 253779 245553 244551 ... slowest runs (cycles): ... 378697 381208 381289 382718 384146 384227 385307 386154 393368 429808 min: 229647 cycles q1: 247842 cycles median: 253038 cycles q3: 367833 cycles max: 429808 cycles RESULT TestThreadCreateAndJoinAfterSettingFaultHandler_CycleCount: gn_x86-64_nnacl_newlib_static= {253038, 119991} count Apparent clock speed: 2733 MHz [ OK ] nacl_newlib.run_performance_test (6820 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/dbg-mac-x86-64/test_results/nacl_clock_cputime_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/src/shared/platform/nacl_clock_test -c [ RUN ] nacl_newlib.run_nacl_clock_cputime_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/src/shared/platform/nacl_clock_test -c [ OK ] nacl_newlib.run_nacl_clock_cputime_test (9020 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/dbg-mac-x86-64/test_results/nacl_interval_multi_reg_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/src/trusted/interval_multiset/nacl_interval_test -k NaClIntervalListMultiset -k NaClIntervalRangeTree -c 1000000 [ RUN ] nacl_newlib.run_nacl_interval_multi_reg_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/src/trusted/interval_multiset/nacl_interval_test -k NaClIntervalListMultiset -k NaClIntervalRangeTree -c 1000000 [ OK ] nacl_newlib.run_nacl_interval_multi_reg_test (990 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/dbg-mac-x86-64/test_results/performance_test.out /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/tests/performance/performance_test gn_trusted_mac_x86-64 [ RUN ] nacl_newlib.run_trusted_performance_test /b/s/w/ir/kitchen-workdir/native_client/scons-out/dbg-mac-x86-64/obj/tests/performance/performance_test gn_trusted_mac_x86-64 TestNull: Measuring real time: 0.040 usec (4e-08 sec) per iteration: 4e-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.62996e-09 sec) per iteration: 0.097406 sec for 37037037 iterations 0.003 usec (2.63075e-09 sec) per iteration: 0.097435 sec for 37037037 iterations 0.003 usec (2.61568e-09 sec) per iteration: 0.096877 sec for 37037037 iterations 0.003 usec (2.64025e-09 sec) per iteration: 0.097787 sec for 37037037 iterations 0.003 usec (2.66263e-09 sec) per iteration: 0.098616 sec for 37037037 iterations mean: 0.002636 usec stddev: 0.000016 usec relative stddev: 0.59% RESULT TestNull: gn_trusted_mac_x86-64= {0.002636, 0.000016} us Measuring clock cycles: first runs (cycles): 297 27 30 30 30 21 18 21 21 21 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 30 39 297 min: 18 cycles q1: 21 cycles median: 27 cycles q3: 30 cycles max: 297 cycles RESULT TestNull_CycleCount: gn_trusted_mac_x86-64= {27, 9} count Apparent clock speed: 10243 MHz TestHostSyscall: Measuring real time: 1.120 usec (1.12e-06 sec) per iteration: 0.000112 sec for 100 iterations 0.965 usec (9.65022e-07 sec) per iteration: 0.086162 sec for 89285 iterations 0.928 usec (9.27636e-07 sec) per iteration: 0.082824 sec for 89285 iterations 0.968 usec (9.67878e-07 sec) per iteration: 0.086417 sec for 89285 iterations 0.932 usec (9.32452e-07 sec) per iteration: 0.083254 sec for 89285 iterations 0.972 usec (9.72302e-07 sec) per iteration: 0.086812 sec for 89285 iterations mean: 0.953058 usec stddev: 0.018995 usec relative stddev: 1.99% RESULT TestHostSyscall: gn_trusted_mac_x86-64= {0.953058, 0.018995} us Measuring clock cycles: first runs (cycles): 3021 2625 2592 2568 2568 2571 2568 2568 2571 2568 ... slowest runs (cycles): ... 2604 2604 2607 2607 2607 2607 2607 2610 2625 3021 min: 2568 cycles q1: 2568 cycles median: 2571 cycles q3: 2595 cycles max: 3021 cycles RESULT TestHostSyscall_CycleCount: gn_trusted_mac_x86-64= {2571, 27} count Apparent clock speed: 2698 MHz TestSetjmpLongjmp: Measuring real time: 5.130 usec (5.13e-06 sec) per iteration: 0.000513 sec for 100 iterations 4.795 usec (4.79495e-06 sec) per iteration: 0.093468 sec for 19493 iterations 4.774 usec (4.77433e-06 sec) per iteration: 0.093066 sec for 19493 iterations 4.745 usec (4.74478e-06 sec) per iteration: 0.09249 sec for 19493 iterations 4.688 usec (4.68784e-06 sec) per iteration: 0.09138 sec for 19493 iterations 4.494 usec (4.49392e-06 sec) per iteration: 0.0876 sec for 19493 iterations mean: 4.699164 usec stddev: 0.108774 usec relative stddev: 2.31% RESULT TestSetjmpLongjmp: gn_trusted_mac_x86-64= {4.699164, 0.108774} us Measuring clock cycles: first runs (cycles): 13803 12522 12477 12543 12483 12483 12483 12480 12486 12546 ... slowest runs (cycles): ... 12528 12531 12543 12543 12546 12576 12582 12585 13803 34155 min: 12474 cycles q1: 12483 cycles median: 12492 cycles q3: 12522 cycles max: 34155 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_trusted_mac_x86-64= {12492, 39} count Apparent clock speed: 2658 MHz TestClockGetTime: Measuring real time: 0.080 usec (8e-08 sec) per iteration: 8e-06 sec for 100 iterations 0.077 usec (7.7e-08 sec) per iteration: 7.7e-05 sec for 1000 iterations 0.078 usec (7.7941e-08 sec) per iteration: 0.101222 sec for 1298701 iterations 0.077 usec (7.7248e-08 sec) per iteration: 0.100322 sec for 1298701 iterations 0.077 usec (7.69107e-08 sec) per iteration: 0.099884 sec for 1298701 iterations 0.077 usec (7.6749e-08 sec) per iteration: 0.099674 sec for 1298701 iterations 0.076 usec (7.59674e-08 sec) per iteration: 0.098659 sec for 1298701 iterations mean: 0.076963 usec stddev: 0.000645 usec relative stddev: 0.84% RESULT TestClockGetTime: gn_trusted_mac_x86-64= {0.076963, 0.000645} us Measuring clock cycles: first runs (cycles): 1767 231 219 234 219 219 216 216 219 219 ... slowest runs (cycles): ... 219 219 219 219 228 228 231 234 252 1767 min: 216 cycles q1: 216 cycles median: 216 cycles q3: 216 cycles max: 1767 cycles RESULT TestClockGetTime_CycleCount: gn_trusted_mac_x86-64= {216, 0} count Apparent clock speed: 2807 MHz TestMmapAnonymous: Measuring real time: 3.500 usec (3.5e-06 sec) per iteration: 0.00035 sec for 100 iterations 3.007 usec (3.00742e-06 sec) per iteration: 0.085925 sec for 28571 iterations 3.022 usec (3.02205e-06 sec) per iteration: 0.086343 sec for 28571 iterations 3.006 usec (3.00599e-06 sec) per iteration: 0.085884 sec for 28571 iterations 3.017 usec (3.01677e-06 sec) per iteration: 0.086192 sec for 28571 iterations 3.062 usec (3.06174e-06 sec) per iteration: 0.087477 sec for 28571 iterations mean: 3.022792 usec stddev: 0.020360 usec relative stddev: 0.67% RESULT TestMmapAnonymous: gn_trusted_mac_x86-64= {3.022792, 0.020360} us Measuring clock cycles: first runs (cycles): 11943 8418 8211 8160 8175 8166 8190 8136 8178 8262 ... slowest runs (cycles): ... 8274 8277 8280 8286 8289 8316 8316 8325 8418 11943 min: 8136 cycles q1: 8172 cycles median: 8187 cycles q3: 8211 cycles max: 11943 cycles RESULT TestMmapAnonymous_CycleCount: gn_trusted_mac_x86-64= {8187, 39} count Apparent clock speed: 2708 MHz TestAtomicIncrement: Measuring real time: 0.010 usec (1e-08 sec) per iteration: 1e-06 sec for 100 iterations 0.011 usec (1.1e-08 sec) per iteration: 1.1e-05 sec for 1000 iterations 0.010 usec (9.57682e-09 sec) per iteration: 0.087062 sec for 9090909 iterations 0.010 usec (9.61631e-09 sec) per iteration: 0.087421 sec for 9090909 iterations 0.010 usec (9.6448e-09 sec) per iteration: 0.08768 sec for 9090909 iterations 0.010 usec (9.55955e-09 sec) per iteration: 0.086905 sec for 9090909 iterations 0.010 usec (9.5238e-09 sec) per iteration: 0.08658 sec for 9090909 iterations mean: 0.009584 usec stddev: 0.000042 usec relative stddev: 0.44% RESULT TestAtomicIncrement: gn_trusted_mac_x86-64= {0.009584, 0.000042} us Measuring clock cycles: first runs (cycles): 339 60 51 54 54 45 54 57 48 54 ... slowest runs (cycles): ... 57 57 57 57 57 57 60 60 72 339 min: 45 cycles q1: 45 cycles median: 48 cycles q3: 54 cycles max: 339 cycles RESULT TestAtomicIncrement_CycleCount: gn_trusted_mac_x86-64= {48, 9} count Apparent clock speed: 5008 MHz TestUncontendedMutexLock: Measuring real time: 0.190 usec (1.9e-07 sec) per iteration: 1.9e-05 sec for 100 iterations 0.030 usec (2.95526e-08 sec) per iteration: 0.015554 sec for 526315 iterations 0.029 usec (2.94101e-08 sec) per iteration: 0.015479 sec for 526315 iterations 0.029 usec (2.94253e-08 sec) per iteration: 0.015487 sec for 526315 iterations 0.029 usec (2.94728e-08 sec) per iteration: 0.015512 sec for 526315 iterations 0.027 usec (2.72821e-08 sec) per iteration: 0.014359 sec for 526315 iterations mean: 0.029029 usec stddev: 0.000875 usec relative stddev: 3.01% RESULT TestUncontendedMutexLock: gn_trusted_mac_x86-64= {0.029029, 0.000875} us Measuring clock cycles: first runs (cycles): 504 102 90 90 93 90 90 90 93 90 ... slowest runs (cycles): ... 93 93 93 93 93 93 93 102 102 504 min: 84 cycles q1: 87 cycles median: 90 cycles q3: 90 cycles max: 504 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_trusted_mac_x86-64= {90, 3} count Apparent clock speed: 3100 MHz TestCondvarSignalNoOp: Measuring real time: 0.100 usec (1e-07 sec) per iteration: 1e-05 sec for 100 iterations 0.015 usec (1.5095e-08 sec) per iteration: 0.015095 sec for 1000000 iterations 0.015 usec (1.4842e-08 sec) per iteration: 0.014842 sec for 1000000 iterations 0.015 usec (1.4806e-08 sec) per iteration: 0.014806 sec for 1000000 iterations 0.015 usec (1.5006e-08 sec) per iteration: 0.015006 sec for 1000000 iterations 0.015 usec (1.5158e-08 sec) per iteration: 0.015158 sec for 1000000 iterations mean: 0.014981 usec stddev: 0.000138 usec relative stddev: 0.92% RESULT TestCondvarSignalNoOp: gn_trusted_mac_x86-64= {0.014981, 0.000138} us Measuring clock cycles: first runs (cycles): 711 78 69 78 69 69 69 66 78 66 ... slowest runs (cycles): ... 78 78 78 78 78 78 78 78 87 711 min: 66 cycles q1: 66 cycles median: 69 cycles q3: 75 cycles max: 711 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_trusted_mac_x86-64= {69, 9} count Apparent clock speed: 4606 MHz TestThreadCreateAndJoin: Measuring real time: 85.640 usec (8.564e-05 sec) per iteration: 0.008564 sec for 100 iterations 82.596 usec (8.25964e-05 sec) per iteration: 0.09639 sec for 1167 iterations 82.351 usec (8.23513e-05 sec) per iteration: 0.096104 sec for 1167 iterations 81.927 usec (8.19272e-05 sec) per iteration: 0.095609 sec for 1167 iterations 83.101 usec (8.31011e-05 sec) per iteration: 0.096979 sec for 1167 iterations 80.630 usec (8.06298e-05 sec) per iteration: 0.094095 sec for 1167 iterations mean: 82.121165 usec stddev: 0.836764 usec relative stddev: 1.02% RESULT TestThreadCreateAndJoin: gn_trusted_mac_x86-64= {82.121165, 0.836764} us Measuring clock cycles: first runs (cycles): 243897 137439 281430 174243 139761 247614 232014 234411 231048 247041 ... slowest runs (cycles): ... 247041 247287 247614 248127 248532 249795 256521 268365 275583 281430 min: 137439 cycles q1: 227415 cycles median: 232230 cycles q3: 237228 cycles max: 281430 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_trusted_mac_x86-64= {232230, 9813} count Apparent clock speed: 2828 MHz TestThreadWakeup: Measuring real time: 20.900 usec (2.09e-05 sec) per iteration: 0.00209 sec for 100 iterations 19.277 usec (1.92774e-05 sec) per iteration: 0.092223 sec for 4784 iterations 19.225 usec (1.92249e-05 sec) per iteration: 0.091972 sec for 4784 iterations 19.127 usec (1.91271e-05 sec) per iteration: 0.091504 sec for 4784 iterations 19.131 usec (1.91315e-05 sec) per iteration: 0.091525 sec for 4784 iterations 19.387 usec (1.93867e-05 sec) per iteration: 0.092746 sec for 4784 iterations mean: 19.229515 usec stddev: 0.097080 usec relative stddev: 0.50% RESULT TestThreadWakeup: gn_trusted_mac_x86-64= {19.229515, 0.097080} us Measuring clock cycles: first runs (cycles): 64449 53529 66987 57396 57975 76044 64260 56388 70443 69012 ... slowest runs (cycles): ... 69771 70443 70452 76044 78810 83214 88038 89382 95301 103020 min: 45810 cycles q1: 50880 cycles median: 51390 cycles q3: 56457 cycles max: 103020 cycles RESULT TestThreadWakeup_CycleCount: gn_trusted_mac_x86-64= {51390, 5577} count Apparent clock speed: 2672 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 ********************************************************************** 3 dbg-mac-x86-64 4 nacl-x86-64 Command return code: 0