[lyakh]

START and RELEASE are already done in task context, move STOP and PAUSE there too.

[lgirdwood]

Some CI red

[lgirdwood]

Can you state the new stop/pause flow in the commit message. I assume we dont have any race for sending reply IPCs that the stream has been stopped or paused.

[lyakh]

Some CI red

@lgirdwood yes, it's still a draft :-) Something broke down along the way, investigating

[gkbldcig]

Can one of the admins verify this patch?

[lgirdwood]

@kkarask @wszypelt can you guys have a look at the CI, I cant see lots of timeout messages (I'm looking at the top red row in the test results) but I cant see the IPC message that is timing out ? Can someone check here, I could be missing something or misunderstanding the logs ? Thanks.
i.e.

16:38:05.119         Timed out after 4 seconds.

16:38:05.713   => Exception in test.
16:38:05.760     Exception TimeoutError occurred at 'C:\\work\\tools\\pyexecnetcache\\cavs_scripts-py\\utilities\\ipc_driver.py':599
                 FW status on IPC timeout after 5.0 seconds:
                 0x00000005 0x00000000 0x00004000

I cant see the IPC that is timing out.

[kkarask]

@lgirdwood I can see that error in the log.log file like here:

Please check log.log files.

[lgirdwood]

@lgirdwood I can see that error in the log.log file like here:

Please check log.log files.

Sorry @kkarask, what I mean is that the error message does not say which IPC has timed out (and there is a lot of IPC traffic in that log)

I assume it's

16:37:56.115         ipc_sent
16:37:56.115         Sending StreamTrigStop (60050000, 00000000)
                     Payload:
                     0000000C 60050000 00000000 

but had to search through.

[kkarask]

@lgirdwood yes, it is the last IPC from FW logs:
[ 5537720.885417] ( 27080.052734) c0 pipe 1.3 ....../pipeline-stream.c:302 INFO pipe trigger cmd 0

In test logs there are no StreamTrigStop received, so timeout occurred.

[lgirdwood]

I wonder if we can get the cosmetic updates in now whilst work continues on the trigger ?

[lgirdwood]

BYT looks like a network or DUT issue. redo CI.

[lgirdwood]

SOFCI TEST

[lyakh]

The previous version was failing all slim-driver tests because all of them issue an IPC sequence of PAUSE + STOP, which never seems to occur under Linux. The reason why this was failing was also rather simple: PAUSE stops the pipeline task and when STOP arrives, the firmware tries to schedule its processing on the pipeline task too, which isn't running any more... I added support for this case and it fixed most of the tests but some are still failing, and the failure looks exactly the same: PAUSE + STOP and the STOP is never replied to. @kkarask @wszypelt any idea what might be different with the still failing cases? Debugging is even more difficult because the DSP logs are truncated, they don't contain the latest entries, so, adding debugging wouldn't help.

[wszypelt]

@marc-hb It looks like the logs took a bit more time and are already available at the link below.
https://sof-ci.01.org/sof-pr-viewer/#/build/PR4724/build7394505

[lyakh]

@wszypelt I think there's an error in this your test:

ERROR test_keyword_get_threshold(), unsupported sample width: 0

As far as I can see from the sources it isn't fatal, in fact it gets ignored by the code, but you might want to correct it.

[wszypelt]

@lyakh Thanks for the info, I will look at it together with our test developer.

[lyakh]

@wszypelt thanks for re-running the tests. @lgirdwood ignoring PCM_PARAMS on active pipelines didn't solve the issue. And it's logical here in fact: I think the second PCM_PARAMS, the failing one, is called when the pipeline isn't active any more but stopped.

[lyakh]

@wszypelt could you also have the following fixed in this test: usually a correct IPC looks in your log something like

15:38:53.577         Sending StreamTrigStop (60050000, 00000000)
                     Payload:
                     0000000C 60050000 00000000

which means, that this is an IPC IPC_STREAM_TRIG_STOP code 0x60050000, and in the payload string you see 3 32-bit values: 2 values make up the header: size of 12, the IPC code itself, and the actual payload value of 0. All looks good. Now, look at the D0i3 command:

15:38:53.577         Sending PmSetD0ix (C8000000, 00000010)
                     Payload:
                     00000008 00000000

That says, that it's sending an IPC code of 0xC8000000, but the raw dump shows a value of 0. Further, 0xc8000000 isn't a valid IPC command either. What the firmware is receiving though is a 0x40080000 code - PM_GATE. Could you please fix those?

[wszypelt]

@wszypelt could you also have the following fixed in this test: usually a correct IPC looks in your log something like

15:38:53.577         Sending StreamTrigStop (60050000, 00000000)
                     Payload:
                     0000000C 60050000 00000000

which means, that this is an IPC IPC_STREAM_TRIG_STOP code 0x60050000, and in the payload string you see 3 32-bit values: 2 values make up the header: size of 12, the IPC code itself, and the actual payload value of 0. All looks good. Now, look at the D0i3 command:

15:38:53.577         Sending PmSetD0ix (C8000000, 00000010)
                     Payload:
                     00000008 00000000

That says, that it's sending an IPC code of 0xC8000000, but the raw dump shows a value of 0. Further, 0xc8000000 isn't a valid IPC command either. What the firmware is receiving though is a 0x40080000 code - PM_GATE. Could you please fix those?

@lyakh Sure thing, we'll try to fix it

[fspychala]

14:47:01,803 | Sending PmGate (40080000, 00000000)
Payload:
00000020 40080000 00000010 00000000 
00000000 00000000 00000000 00000000 

Is that the expected log @lyakh ?

[lyakh]

14:47:01,803 | Sending PmGate (40080000, 00000000)
Payload:
00000020 40080000 00000010 00000000 
00000000 00000000 00000000 00000000 

Is that the expected log @lyakh ?

@fspychala yes, thanks!

[lgirdwood]

@lyakh do you have everything you need now ?

[lyakh]

@lyakh do you have everything you need now ?

@lgirdwood the improvement is good - it shows now data consistent with the firmware log, that makes understanding of these logs easier for future tests. But I don't think this lets me debug and fix this issue if this is what you meant?

[lgirdwood]

@ranj063 @lyakh this and the HDA fix will probably conflict. We should probably merge the HDA fix first the this PR. Any objections or comments ?

[lyakh]

CI: the single failure definitely has nothing to do with this PR:

2021-10-18 15:01:59 UTC [REMOTE_ERROR] There are different sof-logger in PATH on the system sh-adlp-rvp-sdw-01!
3d5fafd583c675bef57ee187278c009b  /usr/local/bin/sof-logger
b8aa1ab6be248f5bdb5b4fe6a8afc4a5  /usr/bin/sof-logger
b8aa1ab6be248f5bdb5b4fe6a8afc4a5  /bin/sof-logger
2021-10-18 15:01:59 UTC [REMOTE_ERROR] Not testing a random sof-logger version

[lyakh]

@ranj063 @lyakh this and the HDA fix will probably conflict. We should probably merge the HDA fix first the this PR. Any objections or comments ?

@lgirdwood yes, we've briefly discussed this with @ranj063 - IIUC with her change there will be an additional IPC before STOP. So, it will also have to be moved to the pipeline task... And so far moving IPCs to the task have been rather complicated. The basic move is pretty simple - just set trigger.cmd to the trigger command that has to be executed in the task context and then add its processing to pipeline_task_cmd() but the devil is as always in the detail.

If we push @ranj063's PR first, I think we'll have to redo this one. We'll have to first move that new additional IPC to the task, then STOP, since it comes after it. But anyway, I think the order should just go with the project time-line / importance?

[lgirdwood]

If we push @ranj063's PR first, I think we'll have to redo this one. We'll have to first move that new additional IPC to the task, then STOP, since it comes after it. But anyway, I think the order should just go with the project time-line / importance?

Yep, we need to fix the HDA bug first and redo this a little afterwards..

[lyakh]

If we push @ranj063's PR first, I think we'll have to redo this one. We'll have to first move that new additional IPC to the task, then STOP, since it comes after it. But anyway, I think the order should just go with the project time-line / importance?

Yep, we need to fix the HDA bug first and redo this a little afterwards..

@lgirdwood looks like (fortunately) I was wrong - no changes are required, any changes, that @ranj063's PR have introduced occur after STOP / PAUSE, so this PR isn't affected. Let me just rebase with no changes and re-push for a test

[lyakh]

CI: https://sof-ci.01.org/sofpr/PR4724/build10823/devicetest/?model=CML_RVP_SDW&testcase=check-suspend-resume-with-playback-5 is a timeout in one of the suspend-resume tests and https://sof-ci.01.org/sofpr/PR4724/build10823/devicetest/?model=BYT_MB_NOCODEC&testcase=check-alsabat-headset-playback is an alsabat test on BYT, neither should be related.

[marc-hb]

Tentative revert in #4920