[==========] 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