QTools  6.3.7
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:

C:\qp\qpc\examples\arm-cm\dpp_efm32-slstk3401a\qxk\gnu>qspy -cCOM6
QSPY host utility 5.9.0
Copyright (c) 2005-2017 Quantum Leaps (state-machine.com)
Time Stamp: 170519_115355
-cCOM6
-v590
-T4
-O4
-F4
-S2
-E2
-Q1
-P2
-B2
-C2

########## Trg-RST  QP-Ver=590,Build=170519_093948
           Obj-Dict 0x000055A6->QS_RX
           Obj-Dict 0x000051F2->l_SysTick_Handler
           Obj-Dict 0x000051F1->l_GPIO_EVEN_IRQHandler
           Usr-Dict 00000070->PHILO_STAT
           Usr-Dict 00000071->PAUSED_STAT
           Usr-Dict 00000072->COMMAND_STAT
           Obj-Dict 0x20000D40->smlPoolSto
           Obj-Dict 0x20000DB4->tableQueueSto
. . . . .
           Obj-Dict 0x200012F8->l_philo<4>
           Obj-Dict 0x20001328->l_philo<4>.timeEvt
           Fun-Dict 0x00000B8D->Philo_initial
           Fun-Dict 0x00000DD5->Philo_thinking
. . . . .
           Sig-Dict 00000010,Obj=0x200011F8->HUNGRY_SIG
           Sig-Dict 00000011,Obj=0x200011F8->TIMEOUT_SIG
===RTC===> St-Init  Obj=l_philo<0>,State=0x00001B05->Philo_thinking
===RTC===> St-Entry Obj=l_philo<0>,State=Philo_thinking
0000190000 Init===> Obj=l_philo<0>,State=Philo_thinking
           Sig-Dict 00000010,Obj=0x20001238->HUNGRY_SIG
. . . . .
===RTC===> St-Init  Obj=l_philo<4>,State=0x00001B05->Philo_thinking
===RTC===> St-Entry Obj=l_philo<4>,State=Philo_thinking
0000190000 Init===> Obj=l_philo<4>,State=Philo_thinking
           Obj-Dict 0x2000133C->l_table
           Fun-Dict 0x00001B05->QHsm_top
. . . . .
           Sig-Dict 00000010,Obj=0x2000133C->HUNGRY_SIG
0000190000 PHILO_STAT 0 thinking
0000190000 PHILO_STAT 1 thinking
0000190000 PHILO_STAT 2 thinking
0000190000 PHILO_STAT 3 thinking
0000190000 PHILO_STAT 4 thinking
===RTC===> St-Init  Obj=l_table,State=QHsm_top->Table_serving
===RTC===> St-Entry Obj=l_table,State=Table_serving
0000190000 Init===> Obj=l_table,State=Table_serving
0000380805 Disp===> Obj=l_table,Sig=SERVE_SIG,State=Table_serving
0000381523 =>Ignore Obj=l_table,Sig=SERVE_SIG,State=Table_serving
0009691003 Disp===> Obj=l_philo<4>,Sig=TIMEOUT_SIG,State=Philo_thinking
===RTC===> St-Exit  Obj=l_philo<4>,State=Philo_thinking
0009692721 Disp===> Obj=l_table,Sig=HUNGRY_SIG,State=Table_serving
0009693389 PHILO_STAT 4 hungry
0009695383 PHILO_STAT 4 eating
0009695932 =>Intern Obj=l_table,Sig=HUNGRY_SIG,State=Table_serving
===RTC===> St-Entry Obj=l_philo<4>,State=Philo_hungry
0009697188 ===>Tran Obj=l_philo<4>,Sig=TIMEOUT_SIG,State=Philo_thinking->Philo_hungry
0009698052 Disp===> Obj=l_philo<4>,Sig=EAT_SIG,State=Philo_hungry
===RTC===> St-Entry Obj=l_philo<4>,State=Philo_eating
0009699697 ===>Tran Obj=l_philo<4>,Sig=EAT_SIG,State=Philo_hungry->Philo_eating
0009700602 Disp===> Obj=l_philo<3>,Sig=EAT_SIG,State=Philo_thinking
0009701247 =>Intern Obj=l_philo<3>,Sig=EAT_SIG,State=Philo_thinking
. . . . . .

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

10 #QS_QF_ACTIVE_ADD <timestamp> AO-Add

an AO has been added to QF (started)

11 #QS_QF_ACTIVE_REMOVE <timestamp> AO-Remov

an AO has been removed from QF (stopped)

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_FIFO <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

18 #QS_QF_EQUEUE_INIT            EQ-Init

an event queue was initialized

19 QS_QF_EQUEUE_POST_FIFO <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

23 #QS_QF_MPOOL_INIT            MP-Init

a memory pool was initialized

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

70 QS_USER + xxx <timestamp> USER+xxx application-specific (user) QS records

Next: QSPY Dictionaries