QTools  6.9.4
Collection of Host-Based Tools
QSPY Screen Output

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