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

[==========] Running 4 tests from 4 test suites. [----------] Global test environment set-up. [----------] 1 test from Oneshot [ RUN ] Oneshot.FillBuffer [INFO:run_test.cc(271)] Running tspec data/oneshot-spawn.tspec, output file /tmp/test.trace [INFO:run_test.cc(213)] Launching: fuchsia-pkg://fuchsia.com/trace#meta/trace.cmx [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [VERBOSE1:trace_manager.cc(202)] Starting configured provider: cpuperf [VERBOSE2:trace_manager.cc(203)] URL: fuchsia-pkg://fuchsia.com/cpuperf_provider#meta/cpuperf_provider.cmx [VERBOSE2:trace_manager.cc(210)] Args: [VERBOSE1:trace_manager.cc(202)] Starting configured provider: ktrace [VERBOSE2:trace_manager.cc(203)] URL: fuchsia-pkg://fuchsia.com/ktrace_provider#meta/ktrace_provider.cmx [VERBOSE2:trace_manager.cc(210)] Args: [INFO:trace_manager.cc(96)] Starting trace with 1 MB buffers, buffering mode=oneshot [VERBOSE2:trace_manager.cc(156)] Registering provider {411135:cpuperf_provider} [VERBOSE1:trace_session.cc(56)] Adding provider #1 {411135:cpuperf_provider}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from ready to started [VERBOSE2:tracee.cc(147)] #1 {411135:cpuperf_provider}: pending=0x3 [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(158)] All providers reporting started [VERBOSE1:trace_session.cc(109)] Marking session as having started [VERBOSE2:trace_manager.cc(156)] Registering provider {411262:ktrace_provider} [VERBOSE1:trace_session.cc(56)] Adding provider #2 {411262:ktrace_provider}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE2:tracee.cc(147)] #2 {411262:ktrace_provider}: pending=0x3 [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(158)] All providers reporting started [VERBOSE2:trace_manager.cc(156)] Registering provider {411402:fill-buffer} [VERBOSE1:trace_session.cc(56)] Adding provider #3 {411402:fill-buffer}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #3 {411402:fill-buffer}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE2:tracee.cc(579)] #3 {411402:fill-buffer}: writing provider info record [WARNING:garnet/bin/trace_manager/tracee.cc(369)] #3 {411402:fill-buffer}: 43698 records were dropped [VERBOSE2:tracee.cc(271)] #3 {411402:fill-buffer}: Writing chunk for rolling buffer 0: vmo offset 0x80, size 0xfff80, by-record [INFO:tracee.cc(435)] #3 {411402:fill-buffer} trace stats [INFO:tracee.cc(436)] Wrapped count: 0 [INFO:tracee.cc(437)] # records dropped: 43698 [INFO:tracee.cc(438)] Durable buffer: 0x0, size 0x0 [INFO:tracee.cc(441)] Non-durable buffer: 0xfff60,0x0, size 0xfff80 [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(158)] All providers reporting started [INFO:trace_manager.cc(135)] Stopping trace [VERBOSE1:trace_session.cc(93)] Stopping trace [VERBOSE2:trace_session.cc(253)] Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from started to stopping [VERBOSE2:tracee.cc(147)] #1 {411135:cpuperf_provider}: pending=0x4 [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #1 {411135:cpuperf_provider}: writing provider info record [VERBOSE2:tracee.cc(271)] #1 {411135:cpuperf_provider}: Writing chunk for rolling buffer 0: vmo offset 0x80, size 0xfff80, by-record [VERBOSE2:tracee.cc(147)] #2 {411262:ktrace_provider}: pending=0x4 [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #2 {411262:ktrace_provider}: writing provider info record [VERBOSE2:tracee.cc(271)] #2 {411262:ktrace_provider}: Writing chunk for rolling buffer 0: vmo offset 0x80, size 0xfff80, by-record [VERBOSE1:trace_session.cc(204)] Marking session as stopped, no more tracees [VERBOSE2:trace_session.cc(253)] Transitioning from stopping to stopped [INFO:trace_manager.cc(138)] Stopped trace [INFO:run_test.cc(239)] Application exited with return reason/code 1/0 [INFO:run_test.cc(261)] return_code 0 [INFO:run_test.cc(296)] Verifying tspec data/oneshot-spawn.tspec, output file /tmp/test.trace [INFO:integration_test_main.cc(63)] /pkgfs/packages/trace_tests/0/bin/basic_integration_test_app started [INFO:integration_test_main.cc(121)] Verifying test /pkgfs/packages/trace_tests/0/data/oneshot-spawn.tspec:"fill-buffer" [ OK ] Oneshot.FillBuffer (4089 ms) [----------] 1 test from Oneshot (4089 ms total) [----------] 1 test from Circular [ RUN ] Circular.FillBuffer [INFO:run_test.cc(271)] Running tspec data/circular.tspec, output file /tmp/test.trace [INFO:run_test.cc(213)] Launching: fuchsia-pkg://fuchsia.com/trace#meta/trace.cmx [INFO:trace_manager.cc(96)] Starting trace with 1 MB buffers, buffering mode=circular [VERBOSE1:trace_session.cc(56)] Adding provider #1 {411135:cpuperf_provider}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from ready to started [VERBOSE1:trace_session.cc(56)] Adding provider #2 {411262:ktrace_provider}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE2:tracee.cc(147)] #1 {411135:cpuperf_provider}: pending=0x3 [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} not ready [VERBOSE2:tracee.cc(147)] #2 {411262:ktrace_provider}: pending=0x3 [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(158)] All providers reporting started [VERBOSE1:trace_session.cc(109)] Marking session as having started [VERBOSE2:trace_manager.cc(156)] Registering provider {412308:fill-buffer} [VERBOSE1:trace_session.cc(56)] Adding provider #4 {412308:fill-buffer}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #4 {412308:fill-buffer}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE2:tracee.cc(579)] #4 {412308:fill-buffer}: writing provider info record [VERBOSE2:tracee.cc(271)] #4 {412308:fill-buffer}: Writing chunk for durable: vmo offset 0x80, size 0xc0, by-size [VERBOSE2:tracee.cc(271)] #4 {412308:fill-buffer}: Writing chunk for rolling buffer 1: vmo offset 0x88040, size 0x77fa0, by-size [VERBOSE2:tracee.cc(271)] #4 {412308:fill-buffer}: Writing chunk for rolling buffer 0: vmo offset 0x10080, size 0x30240, by-size [INFO:tracee.cc(435)] #4 {412308:fill-buffer} trace stats [INFO:tracee.cc(436)] Wrapped count: 6 [INFO:tracee.cc(437)] # records dropped: 0 [INFO:tracee.cc(438)] Durable buffer: 0xc0, size 0x10000 [INFO:tracee.cc(441)] Non-durable buffer: 0x30240,0x77fa0, size 0x77fc0 [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(158)] All providers reporting started [INFO:trace_manager.cc(135)] Stopping trace [VERBOSE1:trace_session.cc(93)] Stopping trace [VERBOSE2:trace_session.cc(253)] Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from started to stopping [VERBOSE2:tracee.cc(147)] #1 {411135:cpuperf_provider}: pending=0x4 [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #1 {411135:cpuperf_provider}: writing provider info record [VERBOSE2:tracee.cc(271)] #1 {411135:cpuperf_provider}: Writing chunk for durable: vmo offset 0x80, size 0x10, by-size [VERBOSE2:tracee.cc(271)] #1 {411135:cpuperf_provider}: Writing chunk for rolling buffer 0: vmo offset 0x10080, size 0x77fc0, by-record [VERBOSE2:tracee.cc(147)] #2 {411262:ktrace_provider}: pending=0x4 [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #2 {411262:ktrace_provider}: writing provider info record [VERBOSE2:tracee.cc(271)] #2 {411262:ktrace_provider}: Writing chunk for durable: vmo offset 0x80, size 0x10, by-size [VERBOSE2:tracee.cc(271)] #2 {411262:ktrace_provider}: Writing chunk for rolling buffer 0: vmo offset 0x10080, size 0x77fc0, by-record [VERBOSE1:trace_session.cc(204)] Marking session as stopped, no more tracees [VERBOSE2:trace_session.cc(253)] Transitioning from stopping to stopped [INFO:trace_manager.cc(138)] Stopped trace [INFO:run_test.cc(239)] Application exited with return reason/code 1/0 [INFO:run_test.cc(261)] return_code 0 [INFO:run_test.cc(296)] Verifying tspec data/circular.tspec, output file /tmp/test.trace [INFO:run_test.cc(213)] Launching: fuchsia-pkg://fuchsia.com/trace_tests#meta/basic_integration_test_app.cmx [INFO:run_test.cc(239)] Application exited with return reason/code 1/0 [INFO:run_test.cc(261)] return_code 0 [ OK ] Circular.FillBuffer (3784 ms) [----------] 1 test from Circular (3784 ms total) [----------] 1 test from Streaming [ RUN ] Streaming.FillBuffer [INFO:run_test.cc(271)] Running tspec data/streaming.tspec, output file /tmp/test.trace [INFO:run_test.cc(213)] Launching: fuchsia-pkg://fuchsia.com/trace#meta/trace.cmx [INFO:trace_manager.cc(96)] Starting trace with 1 MB buffers, buffering mode=streaming [VERBOSE1:trace_session.cc(56)] Adding provider #1 {411135:cpuperf_provider}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from ready to started [VERBOSE1:trace_session.cc(56)] Adding provider #2 {411262:ktrace_provider}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE2:tracee.cc(147)] #1 {411135:cpuperf_provider}: pending=0x3 [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} not ready [VERBOSE2:tracee.cc(147)] #2 {411262:ktrace_provider}: pending=0x3 [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(158)] All providers reporting started [VERBOSE1:trace_session.cc(109)] Marking session as having started [VERBOSE2:trace_manager.cc(156)] Registering provider {413183:fill-buffer} [VERBOSE1:trace_session.cc(56)] Adding provider #5 {413183:fill-buffer}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #5 {413183:fill-buffer}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE2:tracee.cc(579)] #5 {413183:fill-buffer}: writing provider info record [WARNING:garnet/bin/trace_manager/tracee.cc(369)] #5 {413183:fill-buffer}: 45060 records were dropped [VERBOSE2:tracee.cc(271)] #5 {413183:fill-buffer}: Writing chunk for durable: vmo offset 0x80, size 0xc0, by-size [VERBOSE2:tracee.cc(271)] #5 {413183:fill-buffer}: Writing chunk for rolling buffer 0: vmo offset 0x10080, size 0x77fa0, by-size [VERBOSE2:tracee.cc(271)] #5 {413183:fill-buffer}: Writing chunk for rolling buffer 1: vmo offset 0x88040, size 0x77fa0, by-size [INFO:tracee.cc(435)] #5 {413183:fill-buffer} trace stats [INFO:tracee.cc(436)] Wrapped count: 1 [INFO:tracee.cc(437)] # records dropped: 45060 [INFO:tracee.cc(438)] Durable buffer: 0xc0, size 0x10000 [INFO:tracee.cc(441)] Non-durable buffer: 0x77fa0,0x77fa0, size 0x77fc0 [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(158)] All providers reporting started [INFO:trace_manager.cc(135)] Stopping trace [VERBOSE1:trace_session.cc(93)] Stopping trace [VERBOSE2:trace_session.cc(253)] Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from started to stopping [VERBOSE2:tracee.cc(147)] #1 {411135:cpuperf_provider}: pending=0x4 [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #1 {411135:cpuperf_provider}: writing provider info record [VERBOSE2:tracee.cc(271)] #1 {411135:cpuperf_provider}: Writing chunk for durable: vmo offset 0x80, size 0x10, by-size [VERBOSE2:tracee.cc(271)] #1 {411135:cpuperf_provider}: Writing chunk for rolling buffer 0: vmo offset 0x10080, size 0x77fc0, by-record [VERBOSE2:tracee.cc(147)] #2 {411262:ktrace_provider}: pending=0x4 [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #2 {411262:ktrace_provider}: writing provider info record [VERBOSE2:tracee.cc(271)] #2 {411262:ktrace_provider}: Writing chunk for durable: vmo offset 0x80, size 0x10, by-size [VERBOSE2:tracee.cc(271)] #2 {411262:ktrace_provider}: Writing chunk for rolling buffer 0: vmo offset 0x10080, size 0x77fc0, by-record [VERBOSE1:trace_session.cc(204)] Marking session as stopped, no more tracees [VERBOSE2:trace_session.cc(253)] Transitioning from stopping to stopped [INFO:trace_manager.cc(138)] Stopped trace [INFO:run_test.cc(239)] Application exited with return reason/code 1/0 [INFO:run_test.cc(261)] return_code 0 [INFO:run_test.cc(296)] Verifying tspec data/streaming.tspec, output file /tmp/test.trace [INFO:run_test.cc(213)] Launching: fuchsia-pkg://fuchsia.com/trace_tests#meta/basic_integration_test_app.cmx [INFO:run_test.cc(239)] Application exited with return reason/code 1/0 [INFO:run_test.cc(261)] return_code 0 [ OK ] Streaming.FillBuffer (3929 ms) [----------] 1 test from Streaming (3929 ms total) [----------] 1 test from TwoProvidersOneEngine [ RUN ] TwoProvidersOneEngine.ErrorHandling [VERBOSE2:trace_manager.cc(156)] Registering provider {413640:provider1} [VERBOSE2:trace_manager.cc(156)] Registering provider {413640:provider2} [INFO:trace_integration_tests.cc(83)] /pkg/bin/two_providers_one_engine started [INFO:run_test.cc(271)] Running tspec data/simple.tspec, output file /tmp/test.trace [INFO:run_test.cc(213)] Launching: fuchsia-pkg://fuchsia.com/trace#meta/trace.cmx [INFO:trace_manager.cc(96)] Starting trace with 1 MB buffers, buffering mode=oneshot [VERBOSE1:trace_session.cc(56)] Adding provider #1 {411135:cpuperf_provider}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from ready to started [VERBOSE1:trace_session.cc(56)] Adding provider #2 {411262:ktrace_provider}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE1:trace_session.cc(56)] Adding provider #6 {413640:provider1}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #6 {413640:provider1}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE1:trace_session.cc(56)] Adding provider #7 {413640:provider2}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #7 {413640:provider2}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE2:tracee.cc(147)] #2 {411262:ktrace_provider}: pending=0x3 [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} not ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #6 {413640:provider1} not ready [VERBOSE2:trace_session.cc(152)] tracee #7 {413640:provider2} not ready [VERBOSE2:tracee.cc(147)] #1 {411135:cpuperf_provider}: pending=0x3 [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #6 {413640:provider1} not ready [VERBOSE2:trace_session.cc(152)] tracee #7 {413640:provider2} not ready Session: error starting engine, status=-20(ZX_ERR_BAD_STATE) [VERBOSE2:tracee.cc(147)] #7 {413640:provider2}: pending=0x3 [VERBOSE2:tracee.cc(133)] #7 {413640:provider2}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #6 {413640:provider1} not ready [VERBOSE2:trace_session.cc(152)] tracee #7 {413640:provider2} ready [VERBOSE2:tracee.cc(147)] #6 {413640:provider1}: pending=0x4 [VERBOSE2:tracee.cc(133)] #6 {413640:provider1}: Transitioning from start pending to stopped [VERBOSE2:tracee.cc(579)] #6 {413640:provider1}: writing provider info record [ERROR:garnet/bin/trace_manager/tracee.cc(361)] #6 {413640:provider1}: header corrupt, bad magic: 0x0 [ERROR:garnet/bin/trace_manager/trace_session.cc(174)] Problem reading provider output, skipping [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #7 {413640:provider2} ready [VERBOSE2:trace_session.cc(158)] All providers reporting started [VERBOSE1:trace_session.cc(109)] Marking session as having started [VERBOSE2:trace_manager.cc(156)] Registering provider {414164:simple} [VERBOSE1:trace_session.cc(56)] Adding provider #8 {414164:simple}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #8 {414164:simple}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE2:tracee.cc(579)] #8 {414164:simple}: writing provider info record [VERBOSE2:tracee.cc(271)] #8 {414164:simple}: Writing chunk for rolling buffer 0: vmo offset 0x80, size 0xfff80, by-record [INFO:tracee.cc(435)] #8 {414164:simple} trace stats [INFO:tracee.cc(436)] Wrapped count: 0 [INFO:tracee.cc(437)] # records dropped: 0 [INFO:tracee.cc(438)] Durable buffer: 0x0, size 0x0 [INFO:tracee.cc(441)] Non-durable buffer: 0x2a0,0x0, size 0xfff80 [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #7 {413640:provider2} ready [VERBOSE2:trace_session.cc(158)] All providers reporting started [INFO:trace_manager.cc(135)] Stopping trace [VERBOSE1:trace_session.cc(93)] Stopping trace [VERBOSE2:trace_session.cc(253)] Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #7 {413640:provider2}: Transitioning from started to stopping [VERBOSE2:tracee.cc(147)] #2 {411262:ktrace_provider}: pending=0x4 [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #2 {411262:ktrace_provider}: writing provider info record [VERBOSE2:tracee.cc(271)] #2 {411262:ktrace_provider}: Writing chunk for rolling buffer 0: vmo offset 0x80, size 0xfff80, by-record [VERBOSE2:tracee.cc(147)] #1 {411135:cpuperf_provider}: pending=0x4 [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #1 {411135:cpuperf_provider}: writing provider info record [VERBOSE2:tracee.cc(271)] #1 {411135:cpuperf_provider}: Writing chunk for rolling buffer 0: vmo offset 0x80, size 0xfff80, by-record [VERBOSE2:tracee.cc(147)] #7 {413640:provider2}: pending=0x4 [VERBOSE2:tracee.cc(133)] #7 {413640:provider2}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #7 {413640:provider2}: writing provider info record [VERBOSE2:tracee.cc(271)] #7 {413640:provider2}: Writing chunk for rolling buffer 0: vmo offset 0x80, size 0xfff80, by-record [VERBOSE1:trace_session.cc(204)] Marking session as stopped, no more tracees [VERBOSE2:trace_session.cc(253)] Transitioning from stopping to stopped [INFO:trace_manager.cc(138)] Stopped trace [INFO:run_test.cc(239)] Application exited with return reason/code 1/0 [INFO:run_test.cc(261)] return_code 0 [INFO:run_test.cc(296)] Verifying tspec data/simple.tspec, output file /tmp/test.trace [INFO:run_test.cc(213)] Launching: fuchsia-pkg://fuchsia.com/trace_tests#meta/basic_integration_test_app.cmx [INFO:run_test.cc(239)] Application exited with return reason/code 1/0 [INFO:run_test.cc(261)] return_code 0 [INFO:run_test.cc(271)] Running tspec data/simple.tspec, output file /tmp/test.trace [INFO:run_test.cc(213)] Launching: fuchsia-pkg://fuchsia.com/trace#meta/trace.cmx [INFO:trace_manager.cc(96)] Starting trace with 1 MB buffers, buffering mode=oneshot [VERBOSE1:trace_session.cc(56)] Adding provider #1 {411135:cpuperf_provider}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from ready to started [VERBOSE1:trace_session.cc(56)] Adding provider #2 {411262:ktrace_provider}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE1:trace_session.cc(56)] Adding provider #6 {413640:provider1}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #6 {413640:provider1}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE1:trace_session.cc(56)] Adding provider #7 {413640:provider2}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #7 {413640:provider2}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started Session for process 413640: engine is already started. Is there perchance two providers in this app? [VERBOSE2:tracee.cc(147)] #1 {411135:cpuperf_provider}: pending=0x3 [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} not ready [VERBOSE2:trace_session.cc(152)] tracee #6 {413640:provider1} not ready [VERBOSE2:trace_session.cc(152)] tracee #7 {413640:provider2} not ready [VERBOSE2:tracee.cc(147)] #6 {413640:provider1}: pending=0x3 [VERBOSE2:tracee.cc(133)] #6 {413640:provider1}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} not ready [VERBOSE2:trace_session.cc(152)] tracee #6 {413640:provider1} ready [VERBOSE2:trace_session.cc(152)] tracee #7 {413640:provider2} not ready [VERBOSE2:tracee.cc(147)] #7 {413640:provider2}: pending=0x4 [VERBOSE2:tracee.cc(133)] #7 {413640:provider2}: Transitioning from start pending to stopped [VERBOSE2:tracee.cc(579)] #7 {413640:provider2}: writing provider info record [ERROR:garnet/bin/trace_manager/tracee.cc(361)] #7 {413640:provider2}: header corrupt, bad magic: 0x0 [ERROR:garnet/bin/trace_manager/trace_session.cc(174)] Problem reading provider output, skipping [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} not ready [VERBOSE2:trace_session.cc(152)] tracee #6 {413640:provider1} ready [VERBOSE2:tracee.cc(147)] #2 {411262:ktrace_provider}: pending=0x3 [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from start pending to started [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #6 {413640:provider1} ready [VERBOSE2:trace_session.cc(158)] All providers reporting started [VERBOSE1:trace_session.cc(109)] Marking session as having started [VERBOSE2:trace_manager.cc(156)] Registering provider {415044:simple} [VERBOSE1:trace_session.cc(56)] Adding provider #9 {415044:simple}, buffer size 1MB [VERBOSE2:tracee.cc(133)] #9 {415044:simple}: Transitioning from ready to start pending [VERBOSE2:trace_session.cc(253)] Transitioning from started to started [VERBOSE2:tracee.cc(579)] #9 {415044:simple}: writing provider info record [VERBOSE2:tracee.cc(271)] #9 {415044:simple}: Writing chunk for rolling buffer 0: vmo offset 0x80, size 0xfff80, by-record [INFO:tracee.cc(435)] #9 {415044:simple} trace stats [INFO:tracee.cc(436)] Wrapped count: 0 [INFO:tracee.cc(437)] # records dropped: 0 [INFO:tracee.cc(438)] Durable buffer: 0x0, size 0x0 [INFO:tracee.cc(441)] Non-durable buffer: 0x2a0,0x0, size 0xfff80 [VERBOSE2:trace_session.cc(152)] tracee #1 {411135:cpuperf_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #2 {411262:ktrace_provider} ready [VERBOSE2:trace_session.cc(152)] tracee #6 {413640:provider1} ready [VERBOSE2:trace_session.cc(158)] All providers reporting started [INFO:trace_manager.cc(135)] Stopping trace [VERBOSE1:trace_session.cc(93)] Stopping trace [VERBOSE2:trace_session.cc(253)] Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from started to stopping [VERBOSE2:tracee.cc(133)] #6 {413640:provider1}: Transitioning from started to stopping [VERBOSE2:tracee.cc(147)] #1 {411135:cpuperf_provider}: pending=0x4 [VERBOSE2:tracee.cc(133)] #1 {411135:cpuperf_provider}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #1 {411135:cpuperf_provider}: writing provider info record [VERBOSE2:tracee.cc(271)] #1 {411135:cpuperf_provider}: Writing chunk for rolling buffer 0: vmo offset 0x80, size 0xfff80, by-record [VERBOSE2:tracee.cc(147)] #6 {413640:provider1}: pending=0x4 [VERBOSE2:tracee.cc(133)] #6 {413640:provider1}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #6 {413640:provider1}: writing provider info record [VERBOSE2:tracee.cc(271)] #6 {413640:provider1}: Writing chunk for rolling buffer 0: vmo offset 0x80, size 0xfff80, by-record [VERBOSE2:tracee.cc(147)] #2 {411262:ktrace_provider}: pending=0x4 [VERBOSE2:tracee.cc(133)] #2 {411262:ktrace_provider}: Transitioning from stopping to stopped [VERBOSE2:tracee.cc(579)] #2 {411262:ktrace_provider}: writing provider info record [VERBOSE2:tracee.cc(271)] #2 {411262:ktrace_provider}: Writing chunk for rolling buffer 0: vmo offset 0x80, size 0xfff80, by-record [VERBOSE1:trace_session.cc(204)] Marking session as stopped, no more tracees [VERBOSE2:trace_session.cc(253)] Transitioning from stopping to stopped [INFO:trace_manager.cc(138)] Stopped trace [INFO:run_test.cc(239)] Application exited with return reason/code 1/0 [INFO:run_test.cc(261)] return_code 0 [INFO:run_test.cc(296)] Verifying tspec data/simple.tspec, output file /tmp/test.trace [INFO:run_test.cc(213)] Launching: fuchsia-pkg://fuchsia.com/trace_tests#meta/basic_integration_test_app.cmx [INFO:run_test.cc(239)] Application exited with return reason/code 1/0 [INFO:run_test.cc(261)] return_code 0 [INFO:trace_integration_tests.cc(96)] /pkg/bin/two_providers_one_engine terminated [ OK ] TwoProvidersOneEngine.ErrorHandling (1611 ms) [----------] 1 test from TwoProvidersOneEngine (1611 ms total) [----------] Global test environment tear-down [==========] 4 tests from 4 test suites ran. (13413 ms total) [ PASSED ] 4 tests. YOU HAVE 1 DISABLED TEST