Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Tracing with different TPIU baudrates yields different timestamps #137

Open
tmplt opened this issue Jan 25, 2022 · 7 comments
Open

Tracing with different TPIU baudrates yields different timestamps #137

tmplt opened this issue Jan 25, 2022 · 7 comments
Labels
bug Something isn't working upstream This issue is an upstream issue

Comments

@tmplt
Copy link
Member

tmplt commented Jan 25, 2022

With the current implementation reported timestamps are different when tpiu_baud changes.

With tpiu_freq = 120000000 and tpiu_baud = 1000000:

    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: @2084 ns (+2084) [good]: [Task { name: "app::hardware", action: Entered }]
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: @3584 ns (+1500) [good]: [Task { name: "app::software", action: Entered }]
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: @4001 ns (+417) [good]: [Task { name: "app::software", action: Exited }]
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: app::software,3584,4001
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: 
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: @4251 ns (+250) [good]: [Task { name: "app::hardware", action: Returned }, Task { name: "app::hardware", action: Exited }]
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: app::hardware,2084,4251
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: 
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: @8251 ns (+4000) [bad!]: []

With same tpiu_freq and tpiu_baud = 4000000:

   Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: @84 ns (+84) [good]: [Task { name: "app::hardware", action: Entered }, Task { name: "app::software", action: Entered }, Task { name: "app::software", action: Exited }]
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: app::software,84,84
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: 
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: @1751 ns (+1667) [good]: []
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: @2501 ns (+750) [good]: [Task { name: "app::hardware", action: Returned }, Task { name: "app::hardware", action: Exited }]
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy: app::hardware,84,2501
    Frontend /home/tmplt/.cargo/bin/rtic-scope-frontend-dummy:

One would expect timestamps to be the same. On the target, the only difference between the above is the prescaler register: 119 and 29, respectively.

@tmplt tmplt added bug Something isn't working upstream This issue is an upstream issue labels Jan 25, 2022
@tmplt
Copy link
Member Author

tmplt commented Jan 25, 2022

Relevant snippets from documentation:

2022-01-25T09:56:05+01:00

2022-01-25T09:54:24+01:00

@tmplt tmplt changed the title Tracing with different TPIU baudrate yields different timestamps Tracing with different TPIU baudrates yields different timestamps Jan 25, 2022
@tmplt
Copy link
Member Author

tmplt commented Jan 25, 2022

Also related, on account of the different groupings (singular task events in the first output, back-to-back events in the second output):

2022-01-25T10:24:37+01:00

@tmplt
Copy link
Member Author

tmplt commented Jan 25, 2022

Do we see this because state transitions between tracing instances? That is, are we supposed to power cycle the device each time?

@tmplt
Copy link
Member Author

tmplt commented Jan 25, 2022

Do we see this because state transitions between tracing instances?

This is defenitely the case when using the system clock as the local timestamp clock. Timestamps of an initial exception trace packet wildly differ between resets. This should perhaps be expected?

Iteratively tracing (not powercycling) when using the asynchronous TPIU clock is much more determined: I get the same itm-decode output each reset.

@tmplt
Copy link
Member Author

tmplt commented Jan 25, 2022

itm-decode also yield different timestamps when using different baud rates on the SWO pin, set via SWOSCALER: 1Mbps:

ExceptionTrace { exception: Interrupt { irqn: 12 }, action: Entered }
ExceptionTrace { exception: Interrupt { irqn: 13 }, action: Entered }
LocalTimestamp1 { ts: 25, data_relation: Sync }
DataTraceValue { comparator: 1, access_type: Write, value: [0] }
LocalTimestamp1 { ts: 18, data_relation: Sync }
DataTraceValue { comparator: 2, access_type: Write, value: [0] }
ExceptionTrace { exception: Interrupt { irqn: 13 }, action: Exited }
LocalTimestamp2 { ts: 5 }
ExceptionTrace { exception: Interrupt { irqn: 12 }, action: Returned }
ExceptionTrace { exception: Interrupt { irqn: 12 }, action: Exited }
LocalTimestamp2 { ts: 3 }
ExceptionTrace { exception: ThreadMode, action: Returned }
LocalTimestamp1 { ts: 48, data_relation: UnknownAssocEventDelay }

4Mbps:

ExceptionTrace { exception: Interrupt { irqn: 12 }, action: Entered }
ExceptionTrace { exception: Interrupt { irqn: 13 }, action: Entered }
DataTraceValue { comparator: 1, access_type: Write, value: [0] }
DataTraceValue { comparator: 2, access_type: Write, value: [0] }
LocalTimestamp2 { ts: 1 }
ExceptionTrace { exception: Interrupt { irqn: 13 }, action: Exited }
LocalTimestamp1 { ts: 20, data_relation: Sync }
ExceptionTrace { exception: Interrupt { irqn: 12 }, action: Returned }
ExceptionTrace { exception: Interrupt { irqn: 12 }, action: Exited }
LocalTimestamp1 { ts: 9, data_relation: Sync }
ExceptionTrace { exception: ThreadMode, action: Returned }

@tmplt
Copy link
Member Author

tmplt commented Jan 25, 2022

With a smaller prescaler more events are then considered to be back-to-back (no idle time) and insight into the exact timestamps of singular events are lost, but a higher throughput increased timestamp qualities are obtained.

@tmplt
Copy link
Member Author

tmplt commented Jan 25, 2022

But why would timestamp resolution change becauce SWOSCALER is changed?

2022-01-25T11:06:06+01:00

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working upstream This issue is an upstream issue
Projects
None yet
Development

No branches or pull requests

1 participant