Skip to content

[APL] SOF test result depends on the speed of frmware loading #3157

New issue
New issue
Closed
Closed
[APL] SOF test result depends on the speed of frmware loading#3157
Labels
APLApplies to ApolloLake platformbugSomething isn't working

Description

@lyakh
lyakh
opened on Sep 14, 2021

My testing usually looks like (approximately):

scp  dev.machine:x.ri /tmp/
sudo mv /tmp/x.ri /lib/firmware/intel/sof/
sudo modprobe sof
./test

but sometimes I don't rebuild the firmware image and instead want to re-test the existing one. Then I reboot the test device and skip the scp and proceed from the second line. And in some cases the results are consistently different between the two cases. I've seen this multiple times, but I typically discarded this as a human error. Now I again have such a case with a very consistent reproduction. The only explanation I could come up with is that when copying the image over, it's still in kernel's page cache, so, loading it is faster. To verify this theory I rebooted and read-in the image by doing cat x.ri > /dev/null. The test produced the same result as when the image was moved to the firmware directory.
I am not sure what the mitigation should be. We could try to work around this issue by pre-loading the firmware and the topology very early before any hardware access. But then we miss all the bugs that would result from a slow firmware loading. We could also add a parametrised delay where firmware is currently loaded, but then testing volume would grow a lot.

Activity

  1. lyakh
    added
    bugSomething isn't working
    APLApplies to ApolloLake platform
    on Sep 14, 2021

  2. plbossart commented on Sep 14, 2021

    @plbossart
    plbossart
    on Sep 14, 2021
    Member

    @marc-hb reported issues when changing the firmware, precisely because the old one remains in the kernel cache.

    I am not sure how loading the firmware faster would have any impact on results. Loading is either pass or fail, can you elaborate on what you mean by 'fail'? Does the DSP sometimes not boot and run? or do you mean the behavior is different post-boot?

  3. marc-hb commented on Sep 14, 2021

    @marc-hb
    marc-hb
    on Sep 14, 2021
    Collaborator

    @marc-hb reported issues when changing the firmware, precisely because the old one remains in the kernel cache.

    This was fixed by #2954. Also note still mysterious (to me) thesofproject/sof#4419

    Finally, the following FW crash still requires a Linux reboot, reloading the FW is not enough!
    I suspect the FW more this time.

    diff --git a/src/init/init.c b/src/init/init.c
index eb379746129f..08db0eb29887 100644
--- a/src/init/init.c
+++ b/src/init/init.c
@@ -28,6 +28,8 @@
 #include <sof/schedule/ll_schedule_domain.h>
 #include <ipc/trace.h>
 
+extern struct tr_ctx buffer_tr;
+
 /* main firmware context */
 static struct sof sof;
 
@@ -134,11 +136,15 @@ static int primary_core_init(int argc, char *argv[], struct sof *sof)
        interrupt_init(sof);
 #endif /* __ZEPHYR__ */
 
+/* tr_err(&buffer_tr, "CRASHES (and requires a Linux reboot!)"); */
+
 #if CONFIG_TRACE
        trace_point(TRACE_BOOT_SYS_TRACES);
        trace_init(sof);
 #endif
 
+       tr_err(&buffer_tr, "SUPER EARLY trace does not crash");
+
        trace_point(TRACE_BOOT_SYS_NOTIFIER);
        init_system_notify(sof);

    thesofproject/sof@f1531b0810566d

  4. marc-hb commented on Sep 14, 2021

    @marc-hb
    marc-hb
    on Sep 14, 2021
    Collaborator

    Digression sorry:

    scp dev.machine:x.ri /tmp/
    sudo mv /tmp/x.ri /lib/firmware/intel/sof/

    The recent "installer" makefile lets you combine these commands (and more) with a fast, incremental FW build in just one command. It can also deploy the sof-logger and dictionary. It's documented at https://thesofproject.github.io/latest/getting_started/build-guide/build-from-scratch.html#step-3-build-and-sign-firmware-binaries

    sudo modprobe sof

    The official scripts to unload and reload all drivers in the right order can be found https://github.com/thesofproject/sof-test/tree/main/tools/kmod They're used in CI and validation hundreds of times a day.

    Of course you should NOT use these scripts when trying to reproduce this bug as they will change timings and many other things. I just don't want anyone reading this bug to get the wrong impression that each SOF developer has to write their own scp scripts.

    Digression over sorry.

  5. lyakh commented on Sep 15, 2021

    @lyakh
    lyakh
    on Sep 15, 2021
    CollaboratorAuthor

    @marc-hb reported issues when changing the firmware, precisely because the old one remains in the kernel cache.

    I am not sure how loading the firmware faster would have any impact on results. Loading is either pass or fail, can you elaborate on what you mean by 'fail'? Does the DSP sometimes not boot and run? or do you mean the behavior is different post-boot?

    @plbossart I wish I knew why that happens! As I said it's (almost) too close to the miracle status to be acting upon for me, but I've had such cases often enough now and yesterday I really was able to reproduce it reliably for a significant length of time. But no, I don't think it's about a wrong image. There's no other image on the system at that moment (well, not at the path used by the kernel). I checked dmesg - the difference between pre-cached and freshly read-in firmware was like 1-2 vs. 4-5ms. The firmware wasn't failing to load, but the runtime behaviour was different. And I'm putting this in past tense because after a couple of hours that behaviour disappeared. Maybe I hit different NAND cells with a new copy or whatever has happened.
    This doesn't seem like a wide-spread problem so far, but it affected me enough to put it up here. Let's see if anyone else observes anything similar. But we could also make an experiment - move firmware loading to very early in probing. Maybe we're missing a delay in our hardware initialisation sequence and in most cases firmware loading creates that delay for us, but sometimes it doesn't.

  6. plbossart commented on Sep 15, 2021

    @plbossart
    plbossart
    on Sep 15, 2021
    Member

    @lyakh I am still not clear on the errors that you see. Is this post-initialization e.g. while trying to play/record audio, or is this in boot/suspend-resume?

  7. marc-hb commented on Sep 15, 2021

    @marc-hb
    marc-hb
    on Sep 15, 2021
    Collaborator

    And in some cases the results are consistently different between the two cases.

    Can you give an example of a difference?

    the difference between pre-cached and freshly read-in firmware was like 1-2 vs. 4-5ms.

    No test should behave differently because of 3ms delay. The test should just be delayed by 3ms and that's all. If the test behaves differently because of a 3ms delay then there is a race condition and a bug, either in the test itself or in the kernel or in the firmware

    The easiest to reproduce race conditions like these is to manually insert an artificial 3ms delay at the right place in the code - in this case somewhere near the firmware loading?

  8. lyakh commented on Sep 20, 2021

    @lyakh
    lyakh
    on Sep 20, 2021
    CollaboratorAuthor

    @lyakh I am still not clear on the errors that you see. Is this post-initialization e.g. while trying to play/record audio, or is this in boot/suspend-resume?

    @plbossart runtime. In this specific case I was running multiple-pause-resume.

  9. lyakh commented on Sep 20, 2021

    @lyakh
    lyakh
    on Sep 20, 2021
    CollaboratorAuthor

    And in some cases the results are consistently different between the two cases.

    Can you give an example of a difference?

    @marc-hb multiple-pause-resume was failing or passing

  10. ujfalusi commented on Oct 6, 2021

    @ujfalusi
    ujfalusi
    on Oct 6, 2021
    Collaborator

    @lyakh, did you observed the runtime failure in case the firmware is loaded 'faster' or when the firmware is loaded 'slower', that is the firmware loading from filesystem.

  11. lyakh commented on Oct 7, 2021

    @lyakh
    lyakh
    on Oct 7, 2021
    CollaboratorAuthor

    @lyakh, did you observed the runtime failure in case the firmware is loaded 'faster' or when the firmware is loaded 'slower', that is the firmware loading from filesystem.

    @ujfalusi I think the "fast loading" was failing. I.e. when pre-cached by either a fresh scp to the system of a simple cat x.ri > /dev/null, but since this was more than 2 weeks ago, I might be wrong.

  12. plbossart commented on Jun 29, 2022

    @plbossart
    plbossart
    on Jun 29, 2022
    Member

    @lyakh can we close this issue or is this still relevant?

  13. lyakh commented on Jun 30, 2022

    @lyakh
    lyakh
    on Jun 30, 2022
    CollaboratorAuthor

    @lyakh can we close this issue or is this still relevant?

    yes, let's close

  14. lyakh
    closed this as completedon Jun 30, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    APLApplies to ApolloLake platformbugSomething isn't working

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions