Hello guys,
There was an issue reported where the ETM timestamp values would freeze or be 0 sometimes when using perf mode of tracing. This was observed only with perf mode and not sysfs but was reproducible with both ETR and ETF as sinks.
After some debugging, I found that it's mostly to do with CPU idle states. For perf mode, I never see entering CPU_PM_ENTER or EXIT(since the check is mode) and so etm4_cpu_save() and restore() are not called and I believe the contexts are not properly saved and restored across low power states leading to these bad timestamp values. For sysfs tracing, I see save and restore called for respective ETMs when CPUs enter low power states.
For testing, I would run perf record and report commands in a loop.
perf record -e cs_etm/@tmc_etf0/ -N -o perf.data -- some_test perf report -D -i perf.data | grep Timestamp | head
On other shell, I would try to suspend the system:
echo freeze/mem > /sys/power/state
After waking up from suspend, perf commands would continue to run and reports would continue to show either 0 or same timestamps for some period of time.
Even the above test does not always reproduce the issue but the observation that save and restore is not called is always consistent with perf cs mode.
Any idea as to what might be missing for perf mode or if it is expected or some limitation?
Thanks, Sai
On 2020-09-25 16:44, Sai Prakash Ranjan wrote:
Hello guys,
There was an issue reported where the ETM timestamp values would freeze or be 0 sometimes when using perf mode of tracing. This was observed only with perf mode and not sysfs but was reproducible with both ETR and ETF as sinks.
After some debugging, I found that it's mostly to do with CPU idle states. For perf mode, I never see entering CPU_PM_ENTER or EXIT(since the check is mode) and so etm4_cpu_save() and restore() are not called and I believe the contexts are not properly saved and restored across low power states leading to these bad timestamp values. For sysfs tracing, I see save and restore called for respective ETMs when CPUs enter low power states.
For testing, I would run perf record and report commands in a loop.
perf record -e cs_etm/@tmc_etf0/ -N -o perf.data -- some_test perf report -D -i perf.data | grep Timestamp | head
On other shell, I would try to suspend the system:
echo freeze/mem > /sys/power/state
After waking up from suspend, perf commands would continue to run and reports would continue to show either 0 or same timestamps for some period of time.
Even the above test does not always reproduce the issue but the observation that save and restore is not called is always consistent with perf cs mode.
Any idea as to what might be missing for perf mode or if it is expected or some limitation?
I understand different perf trace sessions like how I am trying in a loop shouldn't actually be affected by ETM context save and restore but on same SoC without CPU idle support, the issue is never encountered.
Thanks, Sai
On 09/25/2020 03:48 PM, Sai Prakash Ranjan wrote:
On 2020-09-25 16:44, Sai Prakash Ranjan wrote:
Hello guys,
There was an issue reported where the ETM timestamp values would freeze or be 0 sometimes when using perf mode of tracing. This was observed only with perf mode and not sysfs but was reproducible with both ETR and ETF as sinks.
After some debugging, I found that it's mostly to do with CPU idle states. For perf mode, I never see entering CPU_PM_ENTER or EXIT(since the check is mode) and so etm4_cpu_save() and restore() are not called and I believe the contexts are not properly saved and restored across low power states leading to these bad timestamp values. For sysfs tracing, I see save and restore called for respective ETMs when CPUs enter low power states.
For testing, I would run perf record and report commands in a loop.
perf record -e cs_etm/@tmc_etf0/ -N -o perf.data -- some_test perf report -D -i perf.data | grep Timestamp | head
On other shell, I would try to suspend the system:
echo freeze/mem > /sys/power/state
After waking up from suspend, perf commands would continue to run and reports would continue to show either 0 or same timestamps for some period of time.
Even the above test does not always reproduce the issue but the observation that save and restore is not called is always consistent with perf cs mode.
Any idea as to what might be missing for perf mode or if it is expected or some limitation?
I understand different perf trace sessions like how I am trying in a loop shouldn't actually be affected by ETM context save and restore but on same SoC without CPU idle support, the issue is never encountered.
What is your perf command line ? Do you specify "timestamp" config ?
i.e,
$ perf record -e cs_etm/timestamp,@tmc_etr0/u ..
?
By default the time stamp is not enabled.
Also for the perf events, if they are task bound, the events may not be on when you perform the idles, as the tasks are scheduled out the CPUs going idle. It may be worth checking the system-wide mode where a few CPUs could go idle while the events are on those CPUs.
e.g,
$ perf record -a -e cs_etm// sleep 10000
Suzuki
Hi,
On Fri, 25 Sep 2020 at 16:38, Suzuki K Poulose suzuki.poulose@arm.com wrote:
On 09/25/2020 03:48 PM, Sai Prakash Ranjan wrote:
On 2020-09-25 16:44, Sai Prakash Ranjan wrote:
Hello guys,
There was an issue reported where the ETM timestamp values would freeze or be 0 sometimes when using perf mode of tracing. This was observed only with perf mode and not sysfs but was reproducible with both ETR and ETF as sinks.
After some debugging, I found that it's mostly to do with CPU idle states. For perf mode, I never see entering CPU_PM_ENTER or EXIT(since the check is mode) and so etm4_cpu_save() and restore() are not called and I believe the contexts are not properly saved and restored across low power states leading to these bad timestamp values. For sysfs tracing, I see save and restore called for respective ETMs when CPUs enter low power states.
For testing, I would run perf record and report commands in a loop.
perf record -e cs_etm/@tmc_etf0/ -N -o perf.data -- some_test perf report -D -i perf.data | grep Timestamp | head
On other shell, I would try to suspend the system:
echo freeze/mem > /sys/power/state
After waking up from suspend, perf commands would continue to run and reports would continue to show either 0 or same timestamps for some period of time.
Even the above test does not always reproduce the issue but the observation that save and restore is not called is always consistent with perf cs mode.
Any idea as to what might be missing for perf mode or if it is expected or some limitation?
I understand different perf trace sessions like how I am trying in a loop shouldn't actually be affected by ETM context save and restore but on same SoC without CPU idle support, the issue is never encountered.
What is your perf command line ? Do you specify "timestamp" config ?
i.e,
$ perf record -e cs_etm/timestamp,@tmc_etr0/u ..
?
By default the time stamp is not enabled.
In system wide mode we do automatically enable timestamps to allow perf to correlate the trace streams from different cores.
In the past, 0 or fixed timestamps have been caused by the clock used to drive the timestamp counters not being enabled.
Mike.
Also for the perf events, if they are task bound, the events may not be on when you perform the idles, as the tasks are scheduled out the CPUs going idle. It may be worth checking the system-wide mode where a few CPUs could go idle while the events are on those CPUs.
e.g,
$ perf record -a -e cs_etm// sleep 10000
Suzuki
Hi Mike,
On 2020-09-25 21:28, Mike Leach wrote:
Hi,
On Fri, 25 Sep 2020 at 16:38, Suzuki K Poulose suzuki.poulose@arm.com wrote:
On 09/25/2020 03:48 PM, Sai Prakash Ranjan wrote:
On 2020-09-25 16:44, Sai Prakash Ranjan wrote:
Hello guys,
There was an issue reported where the ETM timestamp values would freeze or be 0 sometimes when using perf mode of tracing. This was observed only with perf mode and not sysfs but was reproducible with both ETR and ETF as sinks.
After some debugging, I found that it's mostly to do with CPU idle states. For perf mode, I never see entering CPU_PM_ENTER or EXIT(since the check is mode) and so etm4_cpu_save() and restore() are not called and I believe the contexts are not properly saved and restored across low power states leading to these bad timestamp values. For sysfs tracing, I see save and restore called for respective ETMs when CPUs enter low power states.
For testing, I would run perf record and report commands in a loop.
perf record -e cs_etm/@tmc_etf0/ -N -o perf.data -- some_test perf report -D -i perf.data | grep Timestamp | head
On other shell, I would try to suspend the system:
echo freeze/mem > /sys/power/state
After waking up from suspend, perf commands would continue to run and reports would continue to show either 0 or same timestamps for some period of time.
Even the above test does not always reproduce the issue but the observation that save and restore is not called is always consistent with perf cs mode.
Any idea as to what might be missing for perf mode or if it is expected or some limitation?
I understand different perf trace sessions like how I am trying in a loop shouldn't actually be affected by ETM context save and restore but on same SoC without CPU idle support, the issue is never encountered.
What is your perf command line ? Do you specify "timestamp" config ?
i.e,
$ perf record -e cs_etm/timestamp,@tmc_etr0/u ..
?
By default the time stamp is not enabled.
In system wide mode we do automatically enable timestamps to allow perf to correlate the trace streams from different cores.
Yes it is enabled by default as you mentioned even without specifying timestamp config for system wide mode.
In the past, 0 or fixed timestamps have been caused by the clock used to drive the timestamp counters not being enabled.
Yes this was the first suspect and so I tried setting CLK_IS_CRITICAL flag so that the clock is not gated ever. So after this, we don't see 0 timestamps but the timestamp freeze (fixed) was still observed. Only thing making a difference was the CPU idle.
Thanks, Sai
Hi Mike,
On 2020-09-25 21:28, Mike Leach wrote:
Hi,
On Fri, 25 Sep 2020 at 16:38, Suzuki K Poulose suzuki.poulose@arm.com wrote:
On 09/25/2020 03:48 PM, Sai Prakash Ranjan wrote:
On 2020-09-25 16:44, Sai Prakash Ranjan wrote:
Hello guys,
There was an issue reported where the ETM timestamp values would freeze or be 0 sometimes when using perf mode of tracing. This was observed only with perf mode and not sysfs but was reproducible with both ETR and ETF as sinks.
After some debugging, I found that it's mostly to do with CPU idle states. For perf mode, I never see entering CPU_PM_ENTER or EXIT(since the check is mode) and so etm4_cpu_save() and restore() are not called and I believe the contexts are not properly saved and restored across low power states leading to these bad timestamp values. For sysfs tracing, I see save and restore called for respective ETMs when CPUs enter low power states.
For testing, I would run perf record and report commands in a loop.
perf record -e cs_etm/@tmc_etf0/ -N -o perf.data -- some_test perf report -D -i perf.data | grep Timestamp | head
On other shell, I would try to suspend the system:
echo freeze/mem > /sys/power/state
After waking up from suspend, perf commands would continue to run and reports would continue to show either 0 or same timestamps for some period of time.
Even the above test does not always reproduce the issue but the observation that save and restore is not called is always consistent with perf cs mode.
Any idea as to what might be missing for perf mode or if it is expected or some limitation?
I understand different perf trace sessions like how I am trying in a loop shouldn't actually be affected by ETM context save and restore but on same SoC without CPU idle support, the issue is never encountered.
What is your perf command line ? Do you specify "timestamp" config ?
i.e,
$ perf record -e cs_etm/timestamp,@tmc_etr0/u ..
?
By default the time stamp is not enabled.
In system wide mode we do automatically enable timestamps to allow perf to correlate the trace streams from different cores.
Yes it is enabled by default as you mentioned even without specifying timestamp config for system wide mode.
In the past, 0 or fixed timestamps have been caused by the clock used to drive the timestamp counters not being enabled.
Yes this was the first suspect and so I tried setting CLK_IS_CRITICAL flag so that the clock is not gated ever. So after this, we don't see 0 timestamps but the timestamp freeze (fixed) was still observed. Only thing making a difference was the CPU idle.
There is nothing in the ETM configuration that could cause zero timestamps or frozen timestamps in trace - if CPU idle manages to restore an ETM state that disables timestamps, you won't see timestamp packets at all. We think what's causing zero or frozen timestamps is a zero or frozen timestamp input to the ETM, from the global timestamp distribution. Somehow, CPU idle has either disabled the global timestamp generator, or disabled something in the timestamp distribution network.
Are you able to see the global timestamp generator in the memory map? If you use csscan.py from https://github.com/ARM-software/CSAL/coresight-tools to scan the ROM table, the timestamp generator might show up as a memory mapped device (or it might not...), if it does, and you can scan it in a zero timestamp situation, you can check if the timestamp generator is enabled.
Al
Thanks, Sai
-- QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum, hosted by The Linux Foundation _______________________________________________ CoreSight mailing list CoreSight@lists.linaro.org https://lists.linaro.org/mailman/listinfo/coresight
Hi Al,
Somehow I couldn't find your message in my codeaurora inbox, so copied your message from coresight list.
On 2020-09-25 21:37, Sai Prakash Ranjan wrote: ... <snip>...
In system wide mode we do automatically enable timestamps to allow perf to correlate the trace streams from different cores.
Yes it is enabled by default as you mentioned even without specifying timestamp config for system wide mode.
In the past, 0 or fixed timestamps have been caused by the clock used to drive the timestamp counters not being enabled.
Yes this was the first suspect and so I tried setting CLK_IS_CRITICAL flag so that the clock is not gated ever. So after this, we don't see 0 timestamps but the timestamp freeze (fixed) was still observed. Only thing making a difference was the CPU idle.
There is nothing in the ETM configuration that could cause zero timestamps or frozen timestamps in trace - if CPU idle manages to restore an ETM state that disables timestamps, you won't see timestamp packets at all. We think what's causing zero or frozen timestamps is a zero or frozen timestamp input to the ETM, from the global timestamp distribution. Somehow, CPU idle has either disabled the global timestamp generator, or disabled something in the timestamp distribution network.
Are you able to see the global timestamp generator in the memory map?
I couldn't find it, I'll have to ask around.
If you use csscan.py from https://github.com/ARM-software/CSAL/coresight-tools to scan the ROM table, the timestamp generator might show up as a memory mapped device (or it might not...), if it does, and you can scan it in a zero timestamp situation, you can check if the timestamp generator is enabled.
The ROM table base address printed 0 with the csinfo module in CSAL. If the csscan.py takes rom table base address? then I guess I won't be able to get timestamp generator info. But nice to know such tools exist.
Thanks, Sai
Hi Al,
Somehow I couldn't find your message in my codeaurora inbox, so copied your message from coresight list.
On 2020-09-25 21:37, Sai Prakash Ranjan wrote: ... <snip>...
In system wide mode we do automatically enable timestamps to allow perf to correlate the trace streams from different cores.
Yes it is enabled by default as you mentioned even without specifying timestamp config for system wide mode.
In the past, 0 or fixed timestamps have been caused by the clock used to drive the timestamp counters not being enabled.
Yes this was the first suspect and so I tried setting CLK_IS_CRITICAL flag so that the clock is not gated ever. So after this, we don't see 0 timestamps but the timestamp freeze (fixed) was still observed. Only thing making a difference was the CPU idle.
There is nothing in the ETM configuration that could cause zero timestamps or frozen timestamps in trace - if CPU idle manages to restore an ETM state that disables timestamps, you won't see timestamp packets at all. We think what's causing zero or frozen timestamps is a zero or frozen timestamp input to the ETM, from the global timestamp distribution. Somehow, CPU idle has either disabled the global timestamp generator, or disabled something in the timestamp distribution network.
Are you able to see the global timestamp generator in the memory map?
I couldn't find it, I'll have to ask around.
If you use csscan.py from https://github.com/ARM-software/CSAL/coresight-tools to scan the ROM table, the timestamp generator might show up as a memory mapped device (or it might not...), if it does, and you can scan it in a zero timestamp situation, you can check if the timestamp generator is enabled.
The ROM table base address printed 0 with the csinfo module in CSAL. If the csscan.py takes rom table base address? then I guess I won't be able to get timestamp generator info. But nice to know such tools exist.
There's almost certainly a ROM table somewhere - if csinfo is showing the base address as 0, it just means the CPU isn't reporting it. You may be able to find it some other way. Generally, if you can find the overall address range allocated to CoreSight blocks, the system ROM table is at the lowest address, and then the table can be used to locate all the other blocks. But every system is different!
Al
Thanks, Sai
-- QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member of Code Aurora Forum, hosted by The Linux Foundation
Hi Al,
On 2020-09-26 01:47, Al Grant wrote:
Hi Al,
Somehow I couldn't find your message in my codeaurora inbox, so copied your message from coresight list.
On 2020-09-25 21:37, Sai Prakash Ranjan wrote: ... <snip>...
In system wide mode we do automatically enable timestamps to allow perf to correlate the trace streams from different cores.
Yes it is enabled by default as you mentioned even without specifying timestamp config for system wide mode.
In the past, 0 or fixed timestamps have been caused by the clock used to drive the timestamp counters not being enabled.
Yes this was the first suspect and so I tried setting CLK_IS_CRITICAL flag so that the clock is not gated ever. So after this, we don't see 0 timestamps but the timestamp freeze (fixed) was still observed. Only thing making a difference was the CPU idle.
There is nothing in the ETM configuration that could cause zero timestamps or frozen timestamps in trace - if CPU idle manages to restore an ETM state that disables timestamps, you won't see timestamp packets at all. We think what's causing zero or frozen timestamps is a zero or frozen timestamp input to the ETM, from the global timestamp distribution. Somehow, CPU idle has either disabled the global timestamp generator, or disabled something in the timestamp distribution network.
Are you able to see the global timestamp generator in the memory map?
I couldn't find it, I'll have to ask around.
If you use csscan.py from https://github.com/ARM-software/CSAL/coresight-tools to scan the ROM table, the timestamp generator might show up as a memory mapped device (or it might not...), if it does, and you can scan it in a zero timestamp situation, you can check if the timestamp generator is enabled.
The ROM table base address printed 0 with the csinfo module in CSAL. If the csscan.py takes rom table base address? then I guess I won't be able to get timestamp generator info. But nice to know such tools exist.
There's almost certainly a ROM table somewhere - if csinfo is showing the base address as 0, it just means the CPU isn't reporting it. You may be able to find it some other way. Generally, if you can find the overall address range allocated to CoreSight blocks, the system ROM table is at the lowest address, and then the table can be used to locate all the other blocks. But every system is different!
Thanks for all this information, very much appreciated, I'll try to collect more details regarding these. BTW looking into etm4 save and restore functions in etm4x driver, I just found that there seems to be a small bug where we save TRCVMIDCCTLR1 also into trcvmidcctlr0 var in etm4_cpu_save() and then write trcvmidcctlr0 into both TRCVMIDCCTLR0 and TRCVMIDCCTLR1 in etm4_cpu_restore(), patch incoming soon. But more surprisingly, after correcting this I am not able to reproduce the timestamp issue which was already very hard to reproduce. I don't understand the relation between these, but I will have to keep an eye on this just in case I am able to reproduce the timestamp issue again.
Thanks, Sai
On 09/26/2020 04:12 PM, Sai Prakash Ranjan wrote:
Hi Al,
On 2020-09-26 01:47, Al Grant wrote:
Hi Al,
Somehow I couldn't find your message in my codeaurora inbox, so copied your message from coresight list.
On 2020-09-25 21:37, Sai Prakash Ranjan wrote: ... <snip>...
In system wide mode we do automatically enable timestamps to allow perf to correlate the trace streams from different cores.
Yes it is enabled by default as you mentioned even without specifying timestamp config for system wide mode.
In the past, 0 or fixed timestamps have been caused by the clock used to drive the timestamp counters not being enabled.
Yes this was the first suspect and so I tried setting CLK_IS_CRITICAL flag so that the clock is not gated ever. So after this, we don't see 0 timestamps but the timestamp freeze (fixed) was still observed. Only thing making a difference was the CPU idle.
There is nothing in the ETM configuration that could cause zero timestamps or frozen timestamps in trace - if CPU idle manages to restore an ETM state that disables timestamps, you won't see timestamp packets at all. We think what's causing zero or frozen timestamps is a zero or frozen timestamp input to the ETM, from the global timestamp distribution. Somehow, CPU idle has either disabled the global timestamp generator, or disabled something in the timestamp distribution network.
Are you able to see the global timestamp generator in the memory map?
I couldn't find it, I'll have to ask around.
If you use csscan.py from https://github.com/ARM-software/CSAL/coresight-tools to scan the ROM table, the timestamp generator might show up as a memory mapped device (or it might not...), if it does, and you can scan it in a zero timestamp situation, you can check if the timestamp generator is enabled.
The ROM table base address printed 0 with the csinfo module in CSAL. If the csscan.py takes rom table base address? then I guess I won't be able to get timestamp generator info. But nice to know such tools exist.
There's almost certainly a ROM table somewhere - if csinfo is showing the base address as 0, it just means the CPU isn't reporting it. You may be able to find it some other way. Generally, if you can find the overall address range allocated to CoreSight blocks, the system ROM table is at the lowest address, and then the table can be used to locate all the other blocks. But every system is different!
Thanks for all this information, very much appreciated, I'll try to collect more details regarding these. BTW looking into etm4 save and restore functions in etm4x driver, I just found that there seems to be a small bug where we save TRCVMIDCCTLR1 also into trcvmidcctlr0 var in etm4_cpu_save() and then write trcvmidcctlr0 into both TRCVMIDCCTLR0 and TRCVMIDCCTLR1 in etm4_cpu_restore(), patch incoming soon. But more surprisingly, after correcting this I am not able to reproduce the timestamp issue which was already very hard to reproduce. I don't understand the relation between these, but I will have to keep an eye on this just in case I am able to reproduce the timestamp issue
I spotted this too and have a patch for this. Also, we have a few issues with the TRC*IDCCTLR1 accesses. I have patches for these too.
Cheers Suzuki
On 2020-09-28 14:54, Suzuki K Poulose wrote:
On 09/26/2020 04:12 PM, Sai Prakash Ranjan wrote:
Hi Al,
On 2020-09-26 01:47, Al Grant wrote:
Hi Al,
Somehow I couldn't find your message in my codeaurora inbox, so copied your message from coresight list.
On 2020-09-25 21:37, Sai Prakash Ranjan wrote: ... <snip>...
In system wide mode we do automatically enable timestamps to allow perf to correlate the trace streams from different cores.
Yes it is enabled by default as you mentioned even without specifying timestamp config for system wide mode.
In the past, 0 or fixed timestamps have been caused by the clock used to drive the timestamp counters not being enabled.
Yes this was the first suspect and so I tried setting CLK_IS_CRITICAL flag so that the clock is not gated ever. So after this, we don't see 0 timestamps but the timestamp freeze (fixed) was still observed. Only thing making a difference was the CPU idle.
There is nothing in the ETM configuration that could cause zero timestamps or frozen timestamps in trace - if CPU idle manages to restore an ETM state that disables timestamps, you won't see timestamp packets at all. We think what's causing zero or frozen timestamps is a zero or frozen timestamp input to the ETM, from the global timestamp distribution. Somehow, CPU idle has either disabled the global timestamp generator, or disabled something in the timestamp distribution network.
Are you able to see the global timestamp generator in the memory map?
I couldn't find it, I'll have to ask around.
If you use csscan.py from https://github.com/ARM-software/CSAL/coresight-tools to scan the ROM table, the timestamp generator might show up as a memory mapped device (or it might not...), if it does, and you can scan it in a zero timestamp situation, you can check if the timestamp generator is enabled.
The ROM table base address printed 0 with the csinfo module in CSAL. If the csscan.py takes rom table base address? then I guess I won't be able to get timestamp generator info. But nice to know such tools exist.
There's almost certainly a ROM table somewhere - if csinfo is showing the base address as 0, it just means the CPU isn't reporting it. You may be able to find it some other way. Generally, if you can find the overall address range allocated to CoreSight blocks, the system ROM table is at the lowest address, and then the table can be used to locate all the other blocks. But every system is different!
Thanks for all this information, very much appreciated, I'll try to collect more details regarding these. BTW looking into etm4 save and restore functions in etm4x driver, I just found that there seems to be a small bug where we save TRCVMIDCCTLR1 also into trcvmidcctlr0 var in etm4_cpu_save() and then write trcvmidcctlr0 into both TRCVMIDCCTLR0 and TRCVMIDCCTLR1 in etm4_cpu_restore(), patch incoming soon. But more surprisingly, after correcting this I am not able to reproduce the timestamp issue which was already very hard to reproduce. I don't understand the relation between these, but I will have to keep an eye on this just in case I am able to reproduce the timestamp issue
I spotted this too and have a patch for this. Also, we have a few issues with the TRC*IDCCTLR1 accesses. I have patches for these too.
I sent the patch yesterday but we can ignore my patch if you are posting other fixes as well.
Thanks, Sai
Hi Suzuki,
On 2020-09-25 21:12, Suzuki K Poulose wrote:
On 09/25/2020 03:48 PM, Sai Prakash Ranjan wrote:
On 2020-09-25 16:44, Sai Prakash Ranjan wrote:
Hello guys,
There was an issue reported where the ETM timestamp values would freeze or be 0 sometimes when using perf mode of tracing. This was observed only with perf mode and not sysfs but was reproducible with both ETR and ETF as sinks.
After some debugging, I found that it's mostly to do with CPU idle states. For perf mode, I never see entering CPU_PM_ENTER or EXIT(since the check is mode) and so etm4_cpu_save() and restore() are not called and I believe the contexts are not properly saved and restored across low power states leading to these bad timestamp values. For sysfs tracing, I see save and restore called for respective ETMs when CPUs enter low power states.
For testing, I would run perf record and report commands in a loop.
perf record -e cs_etm/@tmc_etf0/ -N -o perf.data -- some_test perf report -D -i perf.data | grep Timestamp | head
On other shell, I would try to suspend the system:
echo freeze/mem > /sys/power/state
After waking up from suspend, perf commands would continue to run and reports would continue to show either 0 or same timestamps for some period of time.
Even the above test does not always reproduce the issue but the observation that save and restore is not called is always consistent with perf cs mode.
Any idea as to what might be missing for perf mode or if it is expected or some limitation?
I understand different perf trace sessions like how I am trying in a loop shouldn't actually be affected by ETM context save and restore but on same SoC without CPU idle support, the issue is never encountered.
What is your perf command line ? Do you specify "timestamp" config ?
i.e,
$ perf record -e cs_etm/timestamp,@tmc_etr0/u ..
?
By default the time stamp is not enabled.
perf record -e cs_etm/@tmc_etf0/ -N -o perf.data -- some_test
I do not specify any mode, so I think it is system-wide by default and I do see timestamps without specifying timestamp config as Mike mentioned in other email that it is enabled for system wide mode.
Also for the perf events, if they are task bound, the events may not be on when you perform the idles, as the tasks are scheduled out the CPUs going idle. It may be worth checking the system-wide mode where a few CPUs could go idle while the events are on those CPUs.
e.g,
$ perf record -a -e cs_etm// sleep 10000
Thanks for the example, with this I do see for perf mode tracing, we enter etm save and restore.
Thanks, Sai
-
Al Grant -
Mike Leach -
Sai Prakash Ranjan -
Suzuki K Poulose