QTools  7.4.1
Collection of Host-Based Tools
No Matches
QSPY Screen Output

QSPY Host ApplicationQSPY Dictionaries

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.

In the process of adapting QSPY to support QUTest Unit Testing, the QSPY human-readable 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 textual 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
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 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).

To better adapt QSPY to support QUTest Unit Testing, the QSPY human-readable 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 textual output with the expected output.
State Machine Trace Records (QEP)
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 a transition to history was taken
56 QS_QEP_TRAN_EP ===RTC===> St-EP a transition was taken to an entry point into a submachine
57 QS_QEP_TRAN_XP ===RTC===> St-XP a transition was taken to an exit point out of a submachine
Active Object Trace Records
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 from 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 event to AO failed
Raw Event Queue Trace Records
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 got an event and queue still not empty
22 QS_QF_EQUEUE_GET_LAST <timestamp> EQ-GetL got the last event from the queue
46 QS_QF_EQUEUE_POST_ATTEMPT <timestamp> EQ-PostA attempt to post an event to QEQueue failed
Raw Memory Pool Trace Records
Start of record Comment
24 QS_QF_MPOOL_GET <timestamp> MP-Get 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)
Start of record Comment
26 QS_QF_PUBLISH <timestamp> QF-Pub an event was published
27 QS_QF_NEW_REF <timestamp> New-Ref new event reference was created
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 TickQF system clock tick processing was called
38 QS_QF_DELETE_REF <timestamp> QF-DelRf an event reference is about to be deleted
39 QS_TR_CRIT_ENTRY <timestamp> QF-CritE critical section was entered
40 QS_TR_CRIT_EXIT <timestamp> QF-CritX critical section was exited
41 QS_TR_ISR_ENTRY <timestamp> QF-IsrE an ISR was entered
42 QS_TR_ISR_EXIT <timestamp> QF-IsrX an ISR was exited
Time Events (TE)
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 disarm a disarmed Time Event
35 QS_QF_TIMEEVT_DISARM <timestamp> TE-Dis successful 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
Scheduler Trace Records
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_ENUM_DICT Enum-Dict Enumeration record dictionary entry
Miscellaneous Trace Records
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
67 QS_QUERY_DATA <timestamp> Query-xxx reports the data from "current object" query
68 QS_PEEK_DATA Trg-Peek reports the data from the PEEK query
69 QS_ASSERT_FAIL <timestamp> =ASSERT= Assertion failed in the target
70 QS_QF_RUN QF RUN QF_run() called
User Records (Application Specific)
100 QS_USER + xxx <timestamp> USER+xxx application-specific (user) QS records (100..124)

QSPY Host ApplicationQSPY Dictionaries