ll_scheduler: add check for newly calculated timeout by mrajwa · Pull Request #1768 · thesofproject/sof

mrajwa · 2019-08-27T22:02:41Z

This patch checks if newly created timeout is not a
past time. Such issue will lead to dead scheduler.

NOTE! This will cause slight delay in tasks start time (only when previous tasks took more than scheduled period). I keep investigating what potential consequences it can cause, as for now it looks pretty safe.

Signed-off-by: Marcin Rajwa marcin.rajwa@linux.intel.com

tlauda · 2019-08-28T08:18:24Z

On what platform have you measured it? I think it will differ for different XTAL frequencies.

The amount of ticks should be clock frequency independant. However it is DSP and compiler dependant so I related it with compiler used. I think it should be moved to arch directory as it is valid only for xtensa ISA

tlauda · 2019-08-28T08:37:48Z

Now the question is, why do we have such situation?
What exact tasks have caused this?

mrajwa · 2019-08-28T09:16:27Z

Now the question is, why do we have such situation?
What exact tasks have caused this?

When FW is configured with more advanced, rich topologies like KWD + separate playback/capture or both then on startup and pause/suspend case we sporadically observe such issue. The reproduction rate is about 10%. To be clear 10% of cold starts or pause/suspends result in this issue, any other time we are safe.

lgirdwood · 2019-08-30T21:13:34Z

More efficient to do this

temp_ticks = ll_get_timer(queue) + TICKS_NEEDED_; if (ticks < temp_ticks) ticks = temp_ticks;

Yes sure, there is no need to call ll_get_timer() twice.

tlauda · 2019-09-01T18:22:41Z

@mrajwa We need to add some kind of error message to notify late task processing and also we need to rootcause the reason of such behavior. Based on your description there is still no reason why timer interrupt is handled so late.

mrajwa · 2019-09-02T10:27:30Z

@tlauda, sure, I am OK with error message.
As for what exactly delayed the timer IRQ - as I presumed, it is IPC request which takes more than a millisecond to finish. This IPC request is params() method of KPB component. In that method KPB does a lot - allocated 2,1 second history buffer, clears it, searches for sinks, registers for notifications, initializes draining task and more. I can try to move one or two of these tasks to KPB_new() procedure however it will barely help since the allocation of history buffer alone takes 640 uS.

However this is not the only demanding IPC request. While debugging I have stumbled upon several others which takes like 400-500 uS to accomplish. So if they happen to end up on IRQ list in series before our scheduler handler like IPC_400_uS - IPC_500_uS - TIMER_IRQ we will end up with exact same situation. Although this is much much less likely.

tlauda · 2019-09-02T10:43:19Z

@mrajwa IPC task is executed on lower irq level than timer scheduler, so it should be automatically preempted. We should analyze if the pipeline_params method really needs to disable global interrupts.

mrajwa · 2019-09-03T09:15:19Z

@tlauda, @lgirdwood PR is updated. Can we merge now?

jajanusz · 2019-09-03T14:06:09Z

@mrajwa @tlauda imho it should be platform/arch value

I think it will be overkill in this scenario - it's true that this value is architecture dependent (and we have it wrapped up by precompiler-architecture check) but in the same time it is dependent on scheduler implementation.

@mrajwa it's platform/arch level config, lets put in all in one global place.

tlauda · 2019-09-06T09:18:28Z

SOFCI TEST

jajanusz · 2019-09-10T06:11:03Z

@mrajwa please split it to have irq fix and ticks workaround as separate PRs

mrajwa · 2019-09-10T08:47:38Z

@jajanusz it has just been opened here #1814.

lgirdwood · 2019-09-10T14:37:42Z

@mrajwa Internal CI showing degredation in SNR for TGL ? Can you confirm the is false positive.

mrajwa · 2019-09-10T21:28:15Z

@lgirdwood interesting, where did you see that? Can you give me a reference so I can check? All tests already run passed fine (except pause/resume one but this is known issue)

tlauda · 2019-09-11T11:26:24Z

I don't think we need to check it here. It's calculated from the current time, not last_tick.

Yes the argument to queue_calc_next_timeout() is current time but there is no guarantee the time returned from it will not be past time
return queue->ticks_per_msec * queue->timeout / 1000 + start;

In above statement its enough somebody sets queue->timeout to incorrect value and we may have problems.

To summarise I would keep this check here.

If it's needed then please add some comments to this effect. This way other will understand why we do the check.

tlauda · 2019-09-12T06:20:20Z

SOFCI TEST

tlauda · 2019-09-12T06:22:39Z

The function returns int and here we can have up to 64 bit value.

You suggest to return the 64 bit value which was set I assume. I was also thinking about that but the return of difference, or 0 if there is no diff would be aliggned better with other .set_timer() interfaces like for BYT platform for example. So the ABI is more a like. What do you think?

@mrajwa Are we absolutely sure that the difference will fit into an "int", even in the worse cases where something will delay this code too much?

@mrajwa @paulstelian97 This is what I was talking about. We can potentially have more than 32 bits here.

Fair point, lets make it int64_t then.

In this scenario I also changed the return value itself to be a value written to compare register instead of a difference between requested and set ticks. Even though int64_t max value is half of what uin64_t can offer, it is still enough.

lgirdwood · 2019-09-13T11:02:46Z

If it's needed then please add some comments to this effect. This way other will understand why we do the check.

wenqingfu · 2019-09-16T21:13:25Z

SOFCI TEST

wenqingfu · 2019-09-16T22:17:13Z

it looks pretty safe

massive CI failures. doesn't look safe...

tlauda · 2019-09-17T07:53:24Z

@mrajwa Conflicts.

mrajwa · 2019-09-18T11:23:41Z

@lgirdwood, updated is it OK for you now?

mrajwa · 2019-09-18T11:24:23Z

it looks pretty safe

massive CI failures. doesn't look safe...

It was due to conflicts in one file which happened in the meantime.

lgirdwood · 2019-09-18T13:27:56Z

@mrajwa can you check and comment on the CI errors.

wenqingfu · 2019-09-18T22:23:57Z

Now the two CI test case failures are known issue in firmware/driver. thanks! @mrajwa @lgirdwood

lgirdwood · 2019-09-19T15:01:36Z

@mrajwa good to merge once conflicts fixed.

@tlauda

This adds @tlauda and @mrajwa as codeowners of src\scheduler directory so they will be auto-requested for review in all changes related to files under this directory. Signed-off-by: Marcin Rajwa <marcin.rajwa@linux.intel.com>

This patch reworks cAVS timer_set() interface used to write into timer's compare register. This change takes care of ticks request which are "past time". If such condition occur we set compare register to current time so the latency is minimum. Signed-off-by: Marcin Rajwa <marcin.rajwa@linux.intel.com>

This patch checks if during scheduling we were delayed. If such situation happens we log error message. Signed-off-by: Marcin Rajwa <marcin.rajwa@linux.intel.com>

mrajwa requested review from lbetlej, lgirdwood, mmaka1 and plbossart as code owners August 27, 2019 22:02

mrajwa force-pushed the scheduler_dev branch from 0108475 to c1fb7b4 Compare August 27, 2019 22:10

tlauda suggested changes Aug 28, 2019

View reviewed changes

lgirdwood requested changes Aug 30, 2019

View reviewed changes

mrajwa force-pushed the scheduler_dev branch 2 times, most recently from 965b375 to 1ae0438 Compare September 2, 2019 17:18

This was referenced Sep 2, 2019

[BUG] WoV cannot trigger with topic/sof-dev(kernel) and master(sof) branch #1775

Closed

[BUG]detection trigger failure with GCC toolchain #1648

Closed

[BUG] Keyword detection trigger failure on WHL with S24_LE format #1615

Closed

tlauda approved these changes Sep 3, 2019

View reviewed changes

jajanusz requested a review from lgirdwood September 3, 2019 14:02

jajanusz reviewed Sep 3, 2019

View reviewed changes

mrajwa force-pushed the scheduler_dev branch from 0257c60 to 6249e43 Compare September 9, 2019 22:29

mrajwa force-pushed the scheduler_dev branch from 6249e43 to edd92dd Compare September 10, 2019 09:04

mrajwa requested a review from RanderWang as a code owner September 10, 2019 09:04

mrajwa force-pushed the scheduler_dev branch from edd92dd to 2be89e3 Compare September 10, 2019 10:08

tlauda suggested changes Sep 11, 2019

View reviewed changes

mrajwa force-pushed the scheduler_dev branch from 2be89e3 to eea6fe0 Compare September 11, 2019 12:39

tlauda reviewed Sep 12, 2019

View reviewed changes

mrajwa force-pushed the scheduler_dev branch 2 times, most recently from f0daed8 to ba522d5 Compare September 12, 2019 12:00

tlauda approved these changes Sep 13, 2019

View reviewed changes

lgirdwood requested changes Sep 13, 2019

View reviewed changes

mrajwa force-pushed the scheduler_dev branch 2 times, most recently from 2f86530 to 5dbb445 Compare September 17, 2019 09:34

lgirdwood approved these changes Sep 19, 2019

View reviewed changes

mrajwa added 3 commits September 20, 2019 13:48

timer_domain: check if delay occurred during scheduling

cc148e0

This patch checks if during scheduling we were delayed. If such situation happens we log error message. Signed-off-by: Marcin Rajwa <marcin.rajwa@linux.intel.com>

mrajwa force-pushed the scheduler_dev branch from 5dbb445 to cc148e0 Compare September 20, 2019 11:55

tlauda merged commit ccba8e0 into thesofproject:master Sep 20, 2019

Conversation

mrajwa commented Aug 27, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mrajwa Aug 28, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tlauda commented Aug 28, 2019

Uh oh!

mrajwa commented Aug 28, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tlauda commented Sep 1, 2019

Uh oh!

mrajwa commented Sep 2, 2019

Uh oh!

tlauda commented Sep 2, 2019

Uh oh!

mrajwa commented Sep 3, 2019

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mrajwa Sep 5, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tlauda commented Sep 6, 2019

Uh oh!

jajanusz commented Sep 10, 2019

Uh oh!

mrajwa commented Sep 10, 2019

Uh oh!

lgirdwood commented Sep 10, 2019

Uh oh!

mrajwa commented Sep 10, 2019

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tlauda commented Sep 12, 2019

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

paulstelian97 Sep 12, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mrajwa Sep 12, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

wenqingfu commented Sep 16, 2019

Uh oh!

wenqingfu commented Sep 16, 2019

Uh oh!

mrajwa commented Aug 27, 2019 •

edited

Loading

mrajwa Aug 28, 2019 •

edited

Loading

mrajwa commented Aug 28, 2019 •

edited

Loading

mrajwa Sep 5, 2019 •

edited

Loading

paulstelian97 Sep 12, 2019 •

edited

Loading

mrajwa Sep 12, 2019 •

edited

Loading