QSPY provides a simple consolidated, human-readable textual output to the screen. The readability of this output depends strongly on the availability of the symbolic information about the various objects in the Target code, called dictionaries. If the "dictionaries" are not available, QSPY can output only the hexadecimal values of various object addresses and event signals. However, if QSPY has acquired the dictionaries from the Target, or has read them from a file, it can apply the symbolic information to output the provided identifiers for objects, signals, and states.

Note: In the process of adapting QSPY for supporting QUTest Unit Testing, the QSPY human-redable output has been changed to avoid any special characters used in regular expressions, such as *, [, ], ?, !. This is because the QUTest scripts use regular expressions to match QSPY textuall output with the expected output.

Screen Output Example

For example, the following listing shows the QSPY text output when the dictionaries are available:

QSPY 6.9.0 Copyright (c) 2005-2020 Quantum Leaps
Documentation: https://www.state-machine.com/qtools/qspy.html
Current timestamp: 200827_093625
-c COM7
-u 7701
-v 660
-T 4
-O 4
-F 4
-S 2
-E 2
-Q 1
-P 2
-B 2
-C 2

########## Trg-RST  QP-Ver=690,Build=200824_123230
           Obj-Dict 0x20001048->QS_RX
           Obj-Dict 0x08004009->l_SysTick_Handler
           Usr-Dict 00000100->PHILO_STAT
           Obj-Dict 0x20000EE0->AO_Table
           Obj-Dict 0x20000DDC->AO_Philo[0]
           Obj-Dict 0x20000E10->AO_Philo[1]
           . . . . .
           Obj-Dict 0x20000F94->EvtPool1
           Obj-Dict 0x20000DDC->Philo_inst[0]
           Obj-Dict 0x20000E00->Philo_inst[0].timeEvt
           Obj-Dict 0x20000E10->Philo_inst[1]
           Obj-Dict 0x20000E34->Philo_inst[1].timeEvt
           Obj-Dict 0x20000E44->Philo_inst[2]
           . . . . .
           Fun-Dict 0x080006A9->Philo_initial
           Fun-Dict 0x08000915->Philo_thinking
           Fun-Dict 0x08000871->Philo_hungry
           Fun-Dict 0x080007C5->Philo_eating
           Sig-Dict 00000010,Obj=0x20000DDC->HUNGRY_SIG
           Sig-Dict 00000011,Obj=0x20000DDC->TIMEOUT_SIG
0000000000 AO-Subsc Obj=Philo_inst[0],Sig=00000004,Obj=0x20000DDC
0000000000 AO-Subsc Obj=Philo_inst[0],Sig=00000008,Obj=0x20000DDC
===RTC===> St-Init  Obj=Philo_inst[0],State=0x08001099->Philo_thinking
0000000000 TE0-Arm  Obj=Philo_inst[0].timeEvt,AO=Philo_inst[0],Tim=84,Int=0
===RTC===> St-Entry Obj=Philo_inst[0],State=Philo_thinking
0000000000 Init===> Obj=Philo_inst[0],State=Philo_thinking
           Sig-Dict 00000010,Obj=0x20000E10->HUNGRY_SIG
           Sig-Dict 00000011,Obj=0x20000E10->TIMEOUT_SIG
           . . . . .
           . . . . .
===RTC===> St-Init  Obj=Table_inst,State=0x08001099->Table_serving
===RTC===> St-Entry Obj=Table_inst,State=Table_serving
0000000000 Init===> Obj=Table_inst,State=Table_serving
           QF_RUN
4294946722 QF-Pub   Sdr=l_SysTick_Handler,Evt<Sig=SERVE_SIG,Pool=0,Ref=0>
4294947277 AO-Post  Sdr=l_SysTick_Handler,Obj=Table_inst,Evt<Sig=SERVE_SIG,Pool=0,Ref=0>,Que<Free=5,Min=5>
4294948158 Sch-Next Pri=0->6
4294948490 AO-GetL  Obj=Table_inst,Evt<Sig=SERVE_SIG,Pool=0,Ref=0>
4294949010 Disp===> Obj=Table_inst,Sig=SERVE_SIG,State=Table_serving
4294949660 =>Ignore Obj=Table_inst,Sig=SERVE_SIG,State=Table_serving
4294950254 Sch-Idle Pri=6->0
           TE0-ADis Obj=Philo_inst[4].timeEvt,AO=Philo_inst[4]
4294946907 TE0-Post Obj=Philo_inst[4].timeEvt,Sig=TIMEOUT_SIG,AO=Philo_inst[4]
4294947535 AO-Post  Sdr=l_SysTick_Handler,Obj=Philo_inst[4],Evt<Sig=TIMEOUT_SIG,Pool=0,Ref=0>,Que<Free=5,Min=5>
4294948568 Sch-Next Pri=0->5
4294948900 AO-GetL  Obj=Philo_inst[4],Evt<Sig=TIMEOUT_SIG,Pool=0,Ref=0>
4294949419 Disp===> Obj=Philo_inst[4],Sig=TIMEOUT_SIG,State=Philo_thinking
4294950135 TE0-DisA Obj=Philo_inst[4].timeEvt,AO=Philo_inst[4]
===RTC===> St-Exit  Obj=Philo_inst[4],State=Philo_thinking
4294951090 QF-New   Sig=HUNGRY_SIG,Size=6
4294951506 MP-Get   Obj=EvtPool1,Free=9,Min=9
4294952081 AO-Post  Sdr=Philo_inst[4],Obj=Table_inst,Evt<Sig=HUNGRY_SIG,Pool=1,Ref=1>,Que<Free=5,Min=5>
4294952841 Sch-Next Pri=5->6
4294953173 AO-GetL  Obj=Table_inst,Evt<Sig=HUNGRY_SIG,Pool=1,Ref=1>
4294953692 Disp===> Obj=Table_inst,Sig=HUNGRY_SIG,State=Table_serving
4294954299 PHILO_STAT 4 hungry
4294954817 QF-New   Sig=EAT_SIG,Size=6
4294955233 MP-Get   Obj=EvtPool1,Free=8,Min=8
4294955759 QF-Pub   Sdr=Table_inst,Evt<Sig=EAT_SIG,Pool=1,Ref=0>
4294956277 Sch-Lock Ceil=0->5
4294956667 AO-Post  Sdr=Table_inst,Obj=Philo_inst[4],Evt<Sig=EAT_SIG,Pool=1,Ref=2>,Que<Free=5,Min=5>
4294957464 AO-Post  Sdr=Table_inst,Obj=Philo_inst[3],Evt<Sig=EAT_SIG,Pool=1,Ref=3>,Que<Free=5,Min=5>
4294958261 AO-Post  Sdr=Table_inst,Obj=Philo_inst[2],Evt<Sig=EAT_SIG,Pool=1,Ref=4>,Que<Free=5,Min=5>
4294959058 AO-Post  Sdr=Table_inst,Obj=Philo_inst[1],Evt<Sig=EAT_SIG,Pool=1,Ref=5>,Que<Free=5,Min=5>
4294959855 AO-Post  Sdr=Table_inst,Obj=Philo_inst[0],Evt<Sig=EAT_SIG,Pool=1,Ref=6>,Que<Free=5,Min=5>
4294960624 Sch-Unlk Ceil=5->0
. . . . . .

The QS trace log shown in the listing above contains quite detailed information, because most QS records are enabled (are not blocked in the QS filters). The following bullet items highlight the most interesting parts of the trace and illustrate how you can interpret the trace data:

The QS output starts with the QSPY application version number, the date and time of the run (run time-stamp), and all the options explicitly provided to the QSPY host application.
The first trace records in the log are typically dictionary trace records that provide a mapping between addresses of various objects in memory and their symbolic names.
After the dictionaries, you see the active object initialization. For example, the ===RTC===> St-Init record indicates that the top-most initial transition in the active object l_table has been taken. After this, the ===RTC===> St-Entry record informs you that the state Table_serving has been entered, and finally the record ==>Init tells you that the top-most initial transition sequence has completed. This trace record has a high-resolution time-stamp (the first 10-digit number) generated by the Target. The time units used by this time-stamp depend on the specific hardware timer used in the Target, but typically it is sub-microsecond.
After this you see that at the time-stamp 0000380805 an event was dispatched (Disp===> record) to l_table, but it was subsequently Ignored, while l_table was in the state Table_serving.

Predefined Trace Records

The following table summarizes the text output format used for all predefined QS trace records (see QSpyRecords).

Note: To better adapt QSPY to support QUTest Unit Testing, the QSPY human-redable output has been changed at version 5.9.0 to avoid any special characters used in regular expressions, such as *, [, ], ?, !. This is because the QUTest scripts use regular expressions to match QSPY textuall output with the expected output.

State Machine Trace Records (QEP)
Rec. Num.	Rec. Enum.	Start of record	Comment
1	QS_QEP_STATE_ENTRY	`===RTC===> St-Entry`	a state was entered
2	QS_QEP_STATE_EXIT	`===RTC===> St-Exit`	a state was exited
3	QS_QEP_STATE_INIT	`<timestamp> St-Init`	an initial transition was taken in a state
4	QS_QEP_INIT_TRAN	`<timestamp> Init===>`	the top-most initial transition was taken
5	QS_QEP_INTERN_TRAN	`<timestamp> =>Intern`	an internal transition was taken
6	QS_QEP_TRAN	`<timestamp> ===>Tran`	a regular transition was taken
7	QS_QEP_IGNORED	`<timestamp> =>Ignore`	an event was ignored (silently discarded)
8	QS_QEP_DISPATCH	`<timestamp> Disp===>`	an event was dispatched (begin of RTC step)
9	QS_QEP_UNHANDLED	`===RTC===> St-Unhnd`	a guard prevented handling of an event
55	QS_QEP_TRAN_HIST	`===RTC===> St-Hist`	an a transition to history was taken
56	QS_QEP_TRAN_EP	`===RTC===> St-EP`	an a transition to entry point into a submachine
57	QS_QEP_TRAN_XP	`===RTC===> St-XP`	an a transition to exit point out of a submachine
Active Object Trace Records
Rec. Num.	Rec. Enum.	Start of record	Comment
12	QS_QF_ACTIVE_SUBSCRIBE	`<timestamp> AO-Subsc`	an AO subscribed to an event
13	QS_QF_ACTIVE_UNSUBSCRIBE	`<timestamp> AO-Unsub`	an AO unsubscribed to an event
14	QS_QF_ACTIVE_POST	`<timestamp> AO-Post`	an event was posted (FIFO) directly to AO
15	QS_QF_ACTIVE_POST_LIFO	`<timestamp> AO-LIFO`	an event was posted (LIFO) directly to AO
16	QS_QF_ACTIVE_GET	`<timestamp> AO-Get`	AO got an event and its queue is still not empty
17	QS_QF_ACTIVE_GET_LAST	`<timestamp> AO-GetL`	AO got an event and its queue is empty
45	QS_QF_ACTIVE_POST_ATTEMPT	`<timestamp> AO-PostA`	attempt to post an evt to AO failed
Raw Event Queue Trace Records
Rec. Num.	Rec. Enum.	Start of record	Comment
19	QS_QF_EQUEUE_POST	`<timestamp> EQ-Post`	an event was posted (FIFO) to a raw queue
20	QS_QF_EQUEUE_POST_LIFO	`<timestamp> EQ-LIFO`	an event was posted (LIFO) to a raw queue
21	QS_QF_EQUEUE_GET	`<timestamp> EQ-Get`	get an event and queue still not empty
22	QS_QF_EQUEUE_GET_LAST	`<timestamp> EQ-GetL`	get the last event from the queue
46	QS_QF_EQUEUE_POST_ATTEMPT	`<timestamp> EQ-PostA`	attempt to post an evt to QEQueue failed
Raw Memory Pool Trace Records
Rec. Num.	Rec. Enum.	Start of record	Comment
24	QS_QF_MPOOL_GET	`<timestamp> MP-Get`	a memory block was removed from a memory pool
24	QS_QF_MPOOL_GET_ATTEMPT	`<timestamp> MP-GetA`	a memory block was removed from a memory pool
25	QS_QF_MPOOL_PUT	`<timestamp> MP-Put`	a memory block was returned to a memory pool
47	QS_QF_MPOOL_GET_ATTEMPT	`<timestamp> MP-GetA`	attempt to get a memory block failed
Event Management (QF)
Rec. Num.	Rec. Enum.	Start of record	Comment
26	QS_QF_PUBLISH	`<timestamp> QF-Pub`	an event was published
27	RESERVED
28	QS_QF_NEW	`<timestamp> QF-New`	new event creation
29	QS_QF_GC_ATTEMPT	`<timestamp> QF-gcA`	garbage collection attempt
30	QS_QF_GC	`<timestamp> QF-gc`	garbage collection performed
31	QS_QF_TICK	`Tick`	QF system clock tick processing was called
39	QS_QF_CRIT_ENTRY	`<timestamp> QF-CritE`	critical section was entered
40	QS_QF_CRIT_EXIT	`<timestamp> QF-CritX`	critical section was exited
41	QS_QF_ISR_ENTRY	`<timestamp> QF-IsrE`	an ISR was entered
42	QS_QF_ISR_EXIT	`<timestamp> QF-IsrX`	an ISR was exited
Time Events (TE)
Rec. Num.	Rec. Enum.	Start of record	Comment
32	QS_QF_TIMEEVT_ARM	`<timestamp> TE-Arm`	a time event was armed
33	QS_QF_TIMEEVT_AUTO_DISARM	`<timestamp> TE-ADis`	a time event expired and was disarmed
34	QS_QF_TIMEEVT_DISARM_ATTEMPT	`<timestamp> TE-DisA`	attempt to disarmed a disarmed tevent
35	QS_QF_TIMEEVT_DISARM	`<timestamp> TE-Dis`	true disarming of an armed time event
36	QS_QF_TIMEEVT_REARM	`<timestamp> TE-Rarm`	rearming of a time event
37	QS_QF_TIMEEVT_POST	`<timestamp> TE-Post`	a time event posted itself directly to an AO
38	#QS_QF_TIMEEVT_CTR	`<timestamp> TE-Ctr`	a time event counter was requested
Scheduler Trace Records
Rec. Num.	Rec. Enum.	Start of record	Comment
50	QS_SCHED_LOCK	`<timestamp> Sch-Lock`	scheduler was locked
51	QS_SCHED_UNLOCK	`<timestamp> Sch-Unlk`	scheduler was unlocked
52	QS_SCHED_NEXT	`<timestamp> Sch-Next`	scheduler found next task to execute
53	QS_SCHED_IDLE	`<timestamp> Sch-Idle`	scheduler became idle
54	QS_SCHED_RESUME	`<timestamp> Sch-Rsme`	scheduler resumed previous task (not idle)
Miscellaneous Trace Records NOT MASKABLE WITH THE QS GLOBAL FILTER!
Rec. Num.	Rec. Enum.	Start of record	Comment
58	QS_TEST_PAUSED	`TstPause`	test has been paused
59	QS_TEST_PROBE_GET	`<timestamp> TstProbe`	reports that Test-Probe has been used
60	QS_SIG_DICTIONARY	`Sig-Dict`	signal dictionary entry
61	QS_OBJ_DICTIONARY	`Obj-Dict`	object dictionary entry
62	QS_FUN_DICTIONARY	`Fun-Dict`	function dictionary entry
63	QS_USR_DICTIONARY	`Usr-Dict`	User record dictionary entry
64	QS_TARGET_INFO	`########## Trg-Info`	reports the Target information
65	QS_TARGET_DONE	`<timestamp> Trg-Done`	reports completion of a user callback
66	QS_RX_STATUS	`Trg-Ack`	reports QS data receive status
66	RESERVED
66	QS_PEEK_DATA	`Trg-Peek`	reports the data from the PEEK query
67	QS_ASSERT_FAIL	`<timestamp> =ASSERT=`	Assertion fired
User (Application Specific) Records
100	QS_USER + xxx	`<timestamp> USER+xxx`	application-specific (user) QS records (100..124)

Next: QSPY Dictionaries

Table of Contents

Screen Output Example

Predefined Trace Records