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

Running command: /b/s/w/ir/cache/vpython/4f3597/bin/python scons.py --verbose -k -j1 --mode=nacl,dbg-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,dbg-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/4f3597/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 = 1537186175, usec = 570009 } Mon Sep 17 05:09:35 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: 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 /Applications/Xcode9.3.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/4f3597/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 [48078,2586280832:14:47:53.930777] Native Client module will be loaded at base address 0x0000358000000000 Running suite of 1 benchmarks: Running Benchmark: Life (SIMD version)... RESULT BenchmarkLife: gn_x86-64_nnacl_newlib_static= {0.082710, 0.007310} seconds --------------------------------------------------------------- Done running benchmark suite. [ OK ] nacl_newlib.run_benchmark_test (1000 ms) /b/s/w/ir/cache/vpython/4f3597/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 (66740 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/4f3597/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 [48087,2586280832:14:48:08.302394] Native Client module will be loaded at base address 0x00000e8200000000 TestNull: Measuring real time: 0.010 usec (9.94e-09 sec) per iteration: 9.94e-07 sec for 100 iterations 0.002 usec (2.472e-09 sec) per iteration: 2.472e-06 sec for 1000 iterations 0.002 usec (2.0447e-09 sec) per iteration: 2.0447e-05 sec for 10000 iterations 0.002 usec (2.00869e-09 sec) per iteration: 0.0982386 sec for 48906930 iterations 0.002 usec (2.00183e-09 sec) per iteration: 0.0979032 sec for 48906930 iterations 0.002 usec (2.01207e-09 sec) per iteration: 0.0984041 sec for 48906930 iterations 0.002 usec (2.00412e-09 sec) per iteration: 0.0980154 sec for 48906930 iterations 0.002 usec (2.07444e-09 sec) per iteration: 0.101455 sec for 48906930 iterations mean: 0.002020 usec stddev: 0.000027 usec relative stddev: 1.35% RESULT TestNull: gn_x86-64_nnacl_newlib_static= {0.002020, 0.000027} us Measuring clock cycles: first runs (cycles): 306 21 24 24 21 21 24 21 21 21 ... slowest runs (cycles): ... 33 33 33 33 33 33 36 36 39 306 min: 18 cycles q1: 24 cycles median: 30 cycles q3: 30 cycles max: 306 cycles RESULT TestNull_CycleCount: gn_x86-64_nnacl_newlib_static= {30, 6} count Apparent clock speed: 14850 MHz TestNaClSyscall: Measuring real time: 0.240 usec (2.3961e-07 sec) per iteration: 2.3961e-05 sec for 100 iterations 0.216 usec (2.16391e-07 sec) per iteration: 0.0903095 sec for 417344 iterations 0.220 usec (2.19632e-07 sec) per iteration: 0.091662 sec for 417344 iterations 0.231 usec (2.30718e-07 sec) per iteration: 0.0962887 sec for 417344 iterations 0.223 usec (2.22849e-07 sec) per iteration: 0.0930048 sec for 417344 iterations 0.215 usec (2.14961e-07 sec) per iteration: 0.0897127 sec for 417344 iterations mean: 0.220910 usec stddev: 0.005611 usec relative stddev: 2.54% RESULT TestNaClSyscall: gn_x86-64_nnacl_newlib_static= {0.220910, 0.005611} us Measuring clock cycles: first runs (cycles): 1278 654 519 495 501 492 486 489 489 492 ... slowest runs (cycles): ... 507 519 543 546 546 546 546 546 654 1278 min: 486 cycles q1: 492 cycles median: 492 cycles q3: 498 cycles max: 1278 cycles RESULT TestNaClSyscall_CycleCount: gn_x86-64_nnacl_newlib_static= {492, 6} count Apparent clock speed: 2227 MHz TestSetjmpLongjmp: Measuring real time: 0.019 usec (1.865e-08 sec) per iteration: 1.865e-06 sec for 100 iterations 0.013 usec (1.2626e-08 sec) per iteration: 1.2626e-05 sec for 1000 iterations 0.012 usec (1.21257e-08 sec) per iteration: 0.0960372 sec for 7920164 iterations 0.013 usec (1.34353e-08 sec) per iteration: 0.10641 sec for 7920164 iterations 0.012 usec (1.24224e-08 sec) per iteration: 0.0983878 sec for 7920164 iterations 0.012 usec (1.20343e-08 sec) per iteration: 0.0953132 sec for 7920164 iterations 0.012 usec (1.20771e-08 sec) per iteration: 0.0956526 sec for 7920164 iterations mean: 0.012419 usec stddev: 0.000526 usec relative stddev: 4.24% RESULT TestSetjmpLongjmp: gn_x86-64_nnacl_newlib_static= {0.012419, 0.000526} us Measuring clock cycles: first runs (cycles): 567 60 24 24 24 33 33 33 24 27 ... slowest runs (cycles): ... 36 36 36 36 36 36 36 36 60 567 min: 24 cycles q1: 24 cycles median: 33 cycles q3: 33 cycles max: 567 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_x86-64_nnacl_newlib_static= {33, 9} count Apparent clock speed: 2657 MHz TestClockGetTime: Measuring real time: 0.315 usec (3.1467e-07 sec) per iteration: 3.1467e-05 sec for 100 iterations 0.418 usec (4.1773e-07 sec) per iteration: 0.132752 sec for 317793 iterations 0.306 usec (3.06383e-07 sec) per iteration: 0.0973665 sec for 317793 iterations 0.330 usec (3.29658e-07 sec) per iteration: 0.104763 sec for 317793 iterations 0.306 usec (3.06317e-07 sec) per iteration: 0.0973453 sec for 317793 iterations 0.306 usec (3.05856e-07 sec) per iteration: 0.0971988 sec for 317793 iterations mean: 0.333189 usec stddev: 0.043238 usec relative stddev: 12.98% RESULT TestClockGetTime: gn_x86-64_nnacl_newlib_static= {0.333189, 0.043238} us Measuring clock cycles: first runs (cycles): 3690 1506 1272 1383 1407 1416 1440 1545 1287 1446 ... slowest runs (cycles): ... 1527 1530 1536 1536 1542 1545 1551 1581 1584 3690 min: 1122 cycles q1: 1389 cycles median: 1434 cycles q3: 1500 cycles max: 3690 cycles RESULT TestClockGetTime_CycleCount: gn_x86-64_nnacl_newlib_static= {1434, 111} count Apparent clock speed: 4304 MHz TestTlsVariable: Measuring real time: 0.021 usec (2.147e-08 sec) per iteration: 2.147e-06 sec for 100 iterations 0.012 usec (1.1517e-08 sec) per iteration: 1.1517e-05 sec for 1000 iterations 0.006 usec (6.09252e-09 sec) per iteration: 0.0529003 sec for 8682816 iterations 0.006 usec (6.06586e-09 sec) per iteration: 0.0526688 sec for 8682816 iterations 0.006 usec (6.15438e-09 sec) per iteration: 0.0534374 sec for 8682816 iterations 0.006 usec (6.18056e-09 sec) per iteration: 0.0536647 sec for 8682816 iterations 0.006 usec (6.10892e-09 sec) per iteration: 0.0530426 sec for 8682816 iterations mean: 0.006120 usec stddev: 0.000042 usec relative stddev: 0.68% RESULT TestTlsVariable: gn_x86-64_nnacl_newlib_static= {0.006120, 0.000042} us Measuring clock cycles: first runs (cycles): 345 105 21 33 21 21 24 21 21 21 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 33 105 345 min: 21 cycles q1: 21 cycles median: 21 cycles q3: 30 cycles max: 345 cycles RESULT TestTlsVariable_CycleCount: gn_x86-64_nnacl_newlib_static= {21, 9} count Apparent clock speed: 3431 MHz TestMmapAnonymous: Measuring real time: 10.283 usec (1.02828e-05 sec) per iteration: 0.00102828 sec for 100 iterations 10.040 usec (1.004e-05 sec) per iteration: 0.0976289 sec for 9724 iterations 10.038 usec (1.00385e-05 sec) per iteration: 0.0976141 sec for 9724 iterations 10.007 usec (1.0007e-05 sec) per iteration: 0.0973078 sec for 9724 iterations 9.976 usec (9.97569e-06 sec) per iteration: 0.0970036 sec for 9724 iterations 10.047 usec (1.0047e-05 sec) per iteration: 0.0976974 sec for 9724 iterations mean: 10.021633 usec stddev: 0.026799 usec relative stddev: 0.27% RESULT TestMmapAnonymous: gn_x86-64_nnacl_newlib_static= {10.021633, 0.026799} us Measuring clock cycles: first runs (cycles): 39975 27942 27243 27765 27123 27510 27009 27150 27177 26841 ... slowest runs (cycles): ... 27366 27390 27417 27447 27462 27510 27558 27765 27942 39975 min: 26529 cycles q1: 26871 cycles median: 27036 cycles q3: 27156 cycles max: 39975 cycles RESULT TestMmapAnonymous_CycleCount: gn_x86-64_nnacl_newlib_static= {27036, 285} count Apparent clock speed: 2698 MHz TestAtomicIncrement: Measuring real time: 0.017 usec (1.741e-08 sec) per iteration: 1.741e-06 sec for 100 iterations 0.010 usec (1.0097e-08 sec) per iteration: 1.0097e-05 sec for 1000 iterations 0.010 usec (9.68639e-09 sec) per iteration: 0.0959333 sec for 9903931 iterations 0.010 usec (9.69405e-09 sec) per iteration: 0.0960092 sec for 9903931 iterations 0.010 usec (9.68051e-09 sec) per iteration: 0.0958751 sec for 9903931 iterations 0.010 usec (9.59447e-09 sec) per iteration: 0.0950229 sec for 9903931 iterations 0.010 usec (9.67135e-09 sec) per iteration: 0.0957844 sec for 9903931 iterations mean: 0.009665 usec stddev: 0.000036 usec relative stddev: 0.37% RESULT TestAtomicIncrement: gn_x86-64_nnacl_newlib_static= {0.009665, 0.000036} us Measuring clock cycles: first runs (cycles): 279 51 48 48 51 48 51 39 51 48 ... slowest runs (cycles): ... 51 51 51 51 51 51 51 51 51 279 min: 39 cycles q1: 48 cycles median: 48 cycles q3: 51 cycles max: 279 cycles RESULT TestAtomicIncrement_CycleCount: gn_x86-64_nnacl_newlib_static= {48, 3} count Apparent clock speed: 4966 MHz TestUncontendedMutexLock: Measuring real time: 0.030 usec (2.989e-08 sec) per iteration: 2.989e-06 sec for 100 iterations 0.023 usec (2.3476e-08 sec) per iteration: 2.3476e-05 sec for 1000 iterations 0.023 usec (2.30335e-08 sec) per iteration: 0.0981152 sec for 4259669 iterations 0.023 usec (2.30235e-08 sec) per iteration: 0.0980727 sec for 4259669 iterations 0.023 usec (2.30171e-08 sec) per iteration: 0.0980451 sec for 4259669 iterations 0.023 usec (2.2994e-08 sec) per iteration: 0.0979467 sec for 4259669 iterations 0.023 usec (2.30592e-08 sec) per iteration: 0.0982245 sec for 4259669 iterations mean: 0.023025 usec stddev: 0.000021 usec relative stddev: 0.09% RESULT TestUncontendedMutexLock: gn_x86-64_nnacl_newlib_static= {0.023025, 0.000021} us Measuring clock cycles: first runs (cycles): 459 93 87 90 87 90 87 90 87 90 ... slowest runs (cycles): ... 90 90 90 90 90 90 90 90 93 459 min: 78 cycles q1: 81 cycles median: 87 cycles q3: 90 cycles max: 459 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_x86-64_nnacl_newlib_static= {87, 9} count Apparent clock speed: 3778 MHz TestCondvarSignalNoOp: Measuring real time: 0.394 usec (3.944e-07 sec) per iteration: 3.944e-05 sec for 100 iterations 0.241 usec (2.41269e-07 sec) per iteration: 0.0611735 sec for 253549 iterations 0.240 usec (2.3984e-07 sec) per iteration: 0.0608112 sec for 253549 iterations 0.268 usec (2.67926e-07 sec) per iteration: 0.0679324 sec for 253549 iterations 0.246 usec (2.45749e-07 sec) per iteration: 0.0623094 sec for 253549 iterations 0.249 usec (2.49019e-07 sec) per iteration: 0.0631385 sec for 253549 iterations mean: 0.248761 usec stddev: 0.010121 usec relative stddev: 4.07% RESULT TestCondvarSignalNoOp: gn_x86-64_nnacl_newlib_static= {0.248761, 0.010121} us Measuring clock cycles: first runs (cycles): 2160 690 654 657 651 648 654 663 657 648 ... slowest runs (cycles): ... 663 663 663 663 666 666 690 717 720 2160 min: 642 cycles q1: 648 cycles median: 651 cycles q3: 654 cycles max: 2160 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_x86-64_nnacl_newlib_static= {651, 6} count Apparent clock speed: 2617 MHz TestThreadCreateAndJoin: Measuring real time: 94.707 usec (9.47068e-05 sec) per iteration: 0.00947068 sec for 100 iterations 94.373 usec (9.43729e-05 sec) per iteration: 0.0995635 sec for 1055 iterations 94.182 usec (9.41824e-05 sec) per iteration: 0.0993625 sec for 1055 iterations 95.582 usec (9.55818e-05 sec) per iteration: 0.100839 sec for 1055 iterations 98.927 usec (9.89272e-05 sec) per iteration: 0.104368 sec for 1055 iterations 101.143 usec (0.000101143 sec) per iteration: 0.106706 sec for 1055 iterations mean: 96.841572 usec stddev: 2.742552 usec relative stddev: 2.83% RESULT TestThreadCreateAndJoin: gn_x86-64_nnacl_newlib_static= {96.841572, 2.742552} us Measuring clock cycles: first runs (cycles): 294513 295050 297969 401502 252846 261741 257796 250788 245799 248211 ... slowest runs (cycles): ... 264774 269022 274464 276396 277071 288801 294513 295050 297969 401502 min: 232059 cycles q1: 249171 cycles median: 253128 cycles q3: 256689 cycles max: 401502 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_x86-64_nnacl_newlib_static= {253128, 7518} count Apparent clock speed: 2614 MHz TestThreadWakeup: Measuring real time: 33.961 usec (3.3961e-05 sec) per iteration: 0.0033961 sec for 100 iterations 33.418 usec (3.34182e-05 sec) per iteration: 0.0983831 sec for 2944 iterations 33.067 usec (3.30675e-05 sec) per iteration: 0.0973507 sec for 2944 iterations 33.174 usec (3.31741e-05 sec) per iteration: 0.0976647 sec for 2944 iterations 32.327 usec (3.23267e-05 sec) per iteration: 0.0951697 sec for 2944 iterations 33.283 usec (3.32834e-05 sec) per iteration: 0.0979864 sec for 2944 iterations mean: 33.053973 usec stddev: 0.381811 usec relative stddev: 1.16% RESULT TestThreadWakeup: gn_x86-64_nnacl_newlib_static= {33.053973, 0.381811} us Measuring clock cycles: first runs (cycles): 96393 90366 89016 92763 118287 139146 83532 141729 147705 112560 ... slowest runs (cycles): ... 112560 118287 120141 125358 127224 128859 139146 141729 147705 168033 min: 78318 cycles q1: 86868 cycles median: 87576 cycles q3: 88770 cycles max: 168033 cycles RESULT TestThreadWakeup_CycleCount: gn_x86-64_nnacl_newlib_static= {87576, 1902} count Apparent clock speed: 2649 MHz TestCatchingFault: Measuring real time: 35.515 usec (3.55149e-05 sec) per iteration: 0.00355149 sec for 100 iterations 33.312 usec (3.33115e-05 sec) per iteration: 0.0937719 sec for 2815 iterations 33.122 usec (3.31221e-05 sec) per iteration: 0.0932386 sec for 2815 iterations 33.019 usec (3.30187e-05 sec) per iteration: 0.0929476 sec for 2815 iterations 33.363 usec (3.33627e-05 sec) per iteration: 0.0939159 sec for 2815 iterations 32.976 usec (3.29759e-05 sec) per iteration: 0.092827 sec for 2815 iterations mean: 33.158160 usec stddev: 0.154486 usec relative stddev: 0.47% RESULT TestCatchingFault: gn_x86-64_nnacl_newlib_static= {33.158160, 0.154486} us Measuring clock cycles: first runs (cycles): 147771 183513 103803 96021 144354 112647 123102 115446 153603 131277 ... slowest runs (cycles): ... 116238 121455 123102 131277 131565 144354 147771 153603 181095 183513 min: 85293 cycles q1: 88734 cycles median: 90654 cycles q3: 103803 cycles max: 183513 cycles RESULT TestCatchingFault_CycleCount: gn_x86-64_nnacl_newlib_static= {90654, 15069} count Apparent clock speed: 2734 MHz TestThreadCreateAndJoinAfterSettingFaultHandler: Measuring real time: 94.094 usec (9.40938e-05 sec) per iteration: 0.00940938 sec for 100 iterations 97.490 usec (9.74901e-05 sec) per iteration: 0.103534 sec for 1062 iterations 97.917 usec (9.79166e-05 sec) per iteration: 0.103987 sec for 1062 iterations 102.765 usec (0.000102765 sec) per iteration: 0.109136 sec for 1062 iterations 100.597 usec (0.000100597 sec) per iteration: 0.106834 sec for 1062 iterations 97.307 usec (9.73066e-05 sec) per iteration: 0.10334 sec for 1062 iterations mean: 99.215098 usec stddev: 2.136122 usec relative stddev: 2.15% RESULT TestThreadCreateAndJoinAfterSettingFaultHandler: gn_x86-64_nnacl_newlib_static= {99.215098, 2.136122} us Measuring clock cycles: first runs (cycles): 253605 273510 276771 282708 249033 317091 271761 260253 261495 262707 ... slowest runs (cycles): ... 270531 271761 273009 273510 274497 276771 282708 289065 317091 383796 min: 233307 cycles q1: 250896 cycles median: 253605 cycles q3: 258219 cycles max: 383796 cycles RESULT TestThreadCreateAndJoinAfterSettingFaultHandler_CycleCount: gn_x86-64_nnacl_newlib_static= {253605, 7323} count Apparent clock speed: 2556 MHz [ OK ] nacl_newlib.run_performance_test (6640 ms) /b/s/w/ir/cache/vpython/4f3597/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 (9160 ms) /b/s/w/ir/cache/vpython/4f3597/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 (950 ms) /b/s/w/ir/cache/vpython/4f3597/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.010 usec (1e-08 sec) per iteration: 1e-06 sec for 100 iterations 0.003 usec (3e-09 sec) per iteration: 3e-06 sec for 1000 iterations 0.003 usec (2.7e-09 sec) per iteration: 2.7e-05 sec for 10000 iterations 0.003 usec (2.67224e-09 sec) per iteration: 0.098972 sec for 37037037 iterations 0.003 usec (2.83362e-09 sec) per iteration: 0.104949 sec for 37037037 iterations 0.003 usec (2.65456e-09 sec) per iteration: 0.098317 sec for 37037037 iterations 0.003 usec (2.6548e-09 sec) per iteration: 0.098326 sec for 37037037 iterations 0.003 usec (2.70378e-09 sec) per iteration: 0.10014 sec for 37037037 iterations mean: 0.002704 usec stddev: 0.000067 usec relative stddev: 2.49% RESULT TestNull: gn_trusted_mac_x86-64= {0.002704, 0.000067} us Measuring clock cycles: first runs (cycles): 279 33 30 27 30 30 30 18 21 21 ... slowest runs (cycles): ... 30 30 30 30 30 30 30 33 48 279 min: 18 cycles q1: 21 cycles median: 21 cycles q3: 30 cycles max: 279 cycles RESULT TestNull_CycleCount: gn_trusted_mac_x86-64= {21, 9} count Apparent clock speed: 7767 MHz TestHostSyscall: Measuring real time: 1.180 usec (1.18e-06 sec) per iteration: 0.000118 sec for 100 iterations 1.046 usec (1.04578e-06 sec) per iteration: 0.088625 sec for 84745 iterations 1.051 usec (1.05128e-06 sec) per iteration: 0.089091 sec for 84745 iterations 1.046 usec (1.04628e-06 sec) per iteration: 0.088667 sec for 84745 iterations 1.050 usec (1.04987e-06 sec) per iteration: 0.088971 sec for 84745 iterations 1.047 usec (1.04729e-06 sec) per iteration: 0.088753 sec for 84745 iterations mean: 1.048102 usec stddev: 0.002125 usec relative stddev: 0.20% RESULT TestHostSyscall: gn_trusted_mac_x86-64= {1.048102, 0.002125} us Measuring clock cycles: first runs (cycles): 3093 2838 2799 2793 2802 2787 2799 2793 2802 2790 ... slowest runs (cycles): ... 2826 2826 2826 2826 2829 2838 2865 3018 3093 12348 min: 2784 cycles q1: 2799 cycles median: 2814 cycles q3: 2817 cycles max: 12348 cycles RESULT TestHostSyscall_CycleCount: gn_trusted_mac_x86-64= {2814, 18} count Apparent clock speed: 2685 MHz TestSetjmpLongjmp: Measuring real time: 5.270 usec (5.27e-06 sec) per iteration: 0.000527 sec for 100 iterations 4.781 usec (4.78119e-06 sec) per iteration: 0.090723 sec for 18975 iterations 4.784 usec (4.78398e-06 sec) per iteration: 0.090776 sec for 18975 iterations 4.916 usec (4.91626e-06 sec) per iteration: 0.093286 sec for 18975 iterations 4.899 usec (4.89881e-06 sec) per iteration: 0.092955 sec for 18975 iterations 4.861 usec (4.86082e-06 sec) per iteration: 0.092234 sec for 18975 iterations mean: 4.848211 usec stddev: 0.056512 usec relative stddev: 1.17% RESULT TestSetjmpLongjmp: gn_trusted_mac_x86-64= {4.848211, 0.056512} us Measuring clock cycles: first runs (cycles): 14775 13092 13068 13062 13065 13065 13065 13065 13065 13065 ... slowest runs (cycles): ... 13110 13110 13110 13110 13110 13113 13116 13245 13275 14775 min: 13062 cycles q1: 13065 cycles median: 13098 cycles q3: 13107 cycles max: 14775 cycles RESULT TestSetjmpLongjmp_CycleCount: gn_trusted_mac_x86-64= {13098, 42} count Apparent clock speed: 2702 MHz TestClockGetTime: Measuring real time: 0.090 usec (9e-08 sec) per iteration: 9e-06 sec for 100 iterations 0.077 usec (7.7e-08 sec) per iteration: 7.7e-05 sec for 1000 iterations 0.077 usec (7.7174e-08 sec) per iteration: 0.100226 sec for 1298701 iterations 0.077 usec (7.71309e-08 sec) per iteration: 0.10017 sec for 1298701 iterations 0.076 usec (7.62747e-08 sec) per iteration: 0.099058 sec for 1298701 iterations 0.077 usec (7.71402e-08 sec) per iteration: 0.100182 sec for 1298701 iterations 0.077 usec (7.74666e-08 sec) per iteration: 0.100606 sec for 1298701 iterations mean: 0.077037 usec stddev: 0.000401 usec relative stddev: 0.52% RESULT TestClockGetTime: gn_trusted_mac_x86-64= {0.077037, 0.000401} us Measuring clock cycles: first runs (cycles): 1839 234 228 219 219 219 216 240 219 216 ... slowest runs (cycles): ... 219 219 228 228 228 228 234 240 243 1839 min: 216 cycles q1: 216 cycles median: 219 cycles q3: 219 cycles max: 1839 cycles RESULT TestClockGetTime_CycleCount: gn_trusted_mac_x86-64= {219, 3} count Apparent clock speed: 2843 MHz TestMmapAnonymous: Measuring real time: 4.410 usec (4.41e-06 sec) per iteration: 0.000441 sec for 100 iterations 3.082 usec (3.08207e-06 sec) per iteration: 0.069886 sec for 22675 iterations 3.097 usec (3.09671e-06 sec) per iteration: 0.070218 sec for 22675 iterations 3.070 usec (3.06955e-06 sec) per iteration: 0.069602 sec for 22675 iterations 3.121 usec (3.12071e-06 sec) per iteration: 0.070762 sec for 22675 iterations 3.106 usec (3.10624e-06 sec) per iteration: 0.070434 sec for 22675 iterations mean: 3.095056 usec stddev: 0.017916 usec relative stddev: 0.58% RESULT TestMmapAnonymous: gn_trusted_mac_x86-64= {3.095056, 0.017916} us Measuring clock cycles: first runs (cycles): 11967 8583 8313 8376 8241 8250 8256 8244 8250 8262 ... slowest runs (cycles): ... 8313 8325 8367 8376 8379 8379 8394 8397 8583 11967 min: 8238 cycles q1: 8256 cycles median: 8262 cycles q3: 8277 cycles max: 11967 cycles RESULT TestMmapAnonymous_CycleCount: gn_trusted_mac_x86-64= {8262, 21} count Apparent clock speed: 2669 MHz TestAtomicIncrement: Measuring real time: 0.010 usec (1e-08 sec) per iteration: 1e-06 sec for 100 iterations 0.010 usec (1e-08 sec) per iteration: 1e-05 sec for 1000 iterations 0.010 usec (9.6179e-09 sec) per iteration: 0.096179 sec for 10000000 iterations 0.010 usec (9.6898e-09 sec) per iteration: 0.096898 sec for 10000000 iterations 0.010 usec (9.652e-09 sec) per iteration: 0.09652 sec for 10000000 iterations 0.010 usec (9.6897e-09 sec) per iteration: 0.096897 sec for 10000000 iterations 0.010 usec (9.7021e-09 sec) per iteration: 0.097021 sec for 10000000 iterations mean: 0.009670 usec stddev: 0.000031 usec relative stddev: 0.32% RESULT TestAtomicIncrement: gn_trusted_mac_x86-64= {0.009670, 0.000031} us Measuring clock cycles: first runs (cycles): 363 60 57 60 54 54 57 60 60 54 ... slowest runs (cycles): ... 60 60 60 60 60 60 66 69 90 363 min: 54 cycles q1: 54 cycles median: 54 cycles q3: 57 cycles max: 363 cycles RESULT TestAtomicIncrement_CycleCount: gn_trusted_mac_x86-64= {54, 3} count Apparent clock speed: 5584 MHz TestUncontendedMutexLock: Measuring real time: 0.220 usec (2.2e-07 sec) per iteration: 2.2e-05 sec for 100 iterations 0.026 usec (2.64066e-08 sec) per iteration: 0.012003 sec for 454545 iterations 0.026 usec (2.64176e-08 sec) per iteration: 0.012008 sec for 454545 iterations 0.026 usec (2.63296e-08 sec) per iteration: 0.011968 sec for 454545 iterations 0.026 usec (2.63824e-08 sec) per iteration: 0.011992 sec for 454545 iterations 0.026 usec (2.63714e-08 sec) per iteration: 0.011987 sec for 454545 iterations mean: 0.026382 usec stddev: 0.000031 usec relative stddev: 0.12% RESULT TestUncontendedMutexLock: gn_trusted_mac_x86-64= {0.026382, 0.000031} us Measuring clock cycles: first runs (cycles): 618 111 102 102 99 102 93 105 102 93 ... slowest runs (cycles): ... 102 102 102 102 102 105 105 111 129 618 min: 90 cycles q1: 99 cycles median: 102 cycles q3: 102 cycles max: 618 cycles RESULT TestUncontendedMutexLock_CycleCount: gn_trusted_mac_x86-64= {102, 3} count Apparent clock speed: 3866 MHz TestCondvarSignalNoOp: Measuring real time: 0.110 usec (1.1e-07 sec) per iteration: 1.1e-05 sec for 100 iterations 0.015 usec (1.51778e-08 sec) per iteration: 0.013798 sec for 909090 iterations 0.015 usec (1.53538e-08 sec) per iteration: 0.013958 sec for 909090 iterations 0.017 usec (1.70632e-08 sec) per iteration: 0.015512 sec for 909090 iterations 0.022 usec (2.22475e-08 sec) per iteration: 0.020225 sec for 909090 iterations 0.015 usec (1.49831e-08 sec) per iteration: 0.013621 sec for 909090 iterations mean: 0.016965 usec stddev: 0.002743 usec relative stddev: 16.17% RESULT TestCondvarSignalNoOp: gn_trusted_mac_x86-64= {0.016965, 0.002743} us Measuring clock cycles: first runs (cycles): 726 87 69 69 69 78 78 69 66 69 ... slowest runs (cycles): ... 78 78 78 78 78 78 78 87 87 726 min: 66 cycles q1: 69 cycles median: 69 cycles q3: 75 cycles max: 726 cycles RESULT TestCondvarSignalNoOp_CycleCount: gn_trusted_mac_x86-64= {69, 6} count Apparent clock speed: 4067 MHz TestThreadCreateAndJoin: Measuring real time: 79.940 usec (7.994e-05 sec) per iteration: 0.007994 sec for 100 iterations 76.696 usec (7.6696e-05 sec) per iteration: 0.09587 sec for 1250 iterations 75.410 usec (7.54096e-05 sec) per iteration: 0.094262 sec for 1250 iterations 78.807 usec (7.88072e-05 sec) per iteration: 0.098509 sec for 1250 iterations 80.928 usec (8.0928e-05 sec) per iteration: 0.10116 sec for 1250 iterations 82.718 usec (8.27176e-05 sec) per iteration: 0.103397 sec for 1250 iterations mean: 78.911680 usec stddev: 2.673398 usec relative stddev: 3.39% RESULT TestThreadCreateAndJoin: gn_trusted_mac_x86-64= {78.911680, 2.673398} us Measuring clock cycles: first runs (cycles): 180051 168435 223011 206817 194586 204342 321000 262317 241797 152208 ... slowest runs (cycles): ... 241797 242703 245664 247830 256320 262317 306030 321000 321102 323040 min: 133026 cycles q1: 142143 cycles median: 145944 cycles q3: 166986 cycles max: 323040 cycles RESULT TestThreadCreateAndJoin_CycleCount: gn_trusted_mac_x86-64= {145944, 24843} count Apparent clock speed: 1849 MHz TestThreadWakeup: Measuring real time: 23.800 usec (2.38e-05 sec) per iteration: 0.00238 sec for 100 iterations 21.873 usec (2.18734e-05 sec) per iteration: 0.09189 sec for 4201 iterations 22.058 usec (2.20576e-05 sec) per iteration: 0.092664 sec for 4201 iterations 22.960 usec (2.29602e-05 sec) per iteration: 0.096456 sec for 4201 iterations 23.277 usec (2.32771e-05 sec) per iteration: 0.097787 sec for 4201 iterations 22.283 usec (2.2283e-05 sec) per iteration: 0.093611 sec for 4201 iterations mean: 22.490264 usec stddev: 0.538640 usec relative stddev: 2.39% RESULT TestThreadWakeup: gn_trusted_mac_x86-64= {22.490264, 0.538640} us Measuring clock cycles: first runs (cycles): 70782 56115 69849 55296 55086 58815 65319 61968 70845 71340 ... slowest runs (cycles): ... 70116 70497 70782 70845 71340 72690 84444 100884 125754 129999 min: 53349 cycles q1: 55173 cycles median: 58971 cycles q3: 63972 cycles max: 129999 cycles RESULT TestThreadWakeup_CycleCount: gn_trusted_mac_x86-64= {58971, 8799} count Apparent clock speed: 2622 MHz WARNING: should have taken less than 2.000000 secs [ OK ] nacl_newlib.run_trusted_performance_test (3940 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