efisubsys_init takes more than a few milliseconds

efisubsys_init takes more than a few milliseconds

[Paul Menzel]

Dear Ard,


According to `initcall_debug`, `efisubsys_init` takes more than a few 
milliseconds to execute on a Dell XPS 13 9370 (Intel(R) Core(TM) 
i7-8550U CPU @ 1.80GHz).

> ```
> […]
> [    0.144474] calling  efisubsys_init+0x0/0x2cf @ 1
> [    0.144474] Registered efivars operations
> [    0.173690] initcall efisubsys_init+0x0/0x2cf returned 0 after 27343 usecs
> […]
> ```

To get a vanilla Linux kernel to boot in well under one second, it’d be 
nice if the time could be improved. Do you know, why it takes so long?

According to `bootgraph.py` from pm-graph [1][2] it takes even a little 
longer.

> efisubsys_init: start=690.841, end=720.493, length(w/o overhead)=31.250 ms, return=0

There are several dozen calls to `virt_efi_get_next_variable()` all but 
one taking around 0.335 ms. This path needs to be optimized. Is that 
possible?

To reproduce this, clone the pm-graph repository [2], use `sudo 
./bootgraph.py -f -fstat -maxdepth 10 -manual` to see what to add to 
`/boot/grub/grub.cfg`. Then reboot, and execute `sudo ./bootgraph.py -f 
-fstat -maxdepth 10`.

If your system is powerful enough, you can use a higher maximum depth. I 
didn’t get around how `-cgfilter` works to get smaller HTML files.


Kind regards,

Paul


[1] https://01.org/suspendresume
[2] https://github.com/01org/pm-graph

Re: efisubsys_init takes more than a few milliseconds

[Ard Biesheuvel]

Hello Paul,

On 24 March 2018 at 22:10, Paul Menzel <pmenzel+linux-efi@molgen.mpg.de> wrote:
> Dear Ard,
>
>
> According to `initcall_debug`, `efisubsys_init` takes more than a few
> milliseconds to execute on a Dell XPS 13 9370 (Intel(R) Core(TM) i7-8550U
> CPU @ 1.80GHz).
>
>> ```
>> […]
>> [ 0.144474] calling  efisubsys_init+0x0/0x2cf @ 1
>> [ 0.144474] Registered efivars operations
>> [ 0.173690] initcall efisubsys_init+0x0/0x2cf returned 0 after 27343 usecs
>> […]
>> ```
>
>
> To get a vanilla Linux kernel to boot in well under one second, it’d be nice
> if the time could be improved. Do you know, why it takes so long?
>
> According to `bootgraph.py` from pm-graph [1][2] it takes even a little
> longer.
>
>> efisubsys_init: start=690.841, end=720.493, length(w/o overhead)=31.250
>> ms, return=0
>
>
> There are several dozen calls to `virt_efi_get_next_variable()` all but one
> taking around 0.335 ms. This path needs to be optimized. Is that possible?
>

That depends. These are firmware calls, so to make these calls faster,
you need to modify the firmware, not the kernel.

We may be able to make more intrusive changes to get rid of this
delay, e.g., spin up a special kernel thread, but I'd have to check in
more detail. In the mean time, you can try passing 'efi=noruntime' to
the kernel.


> To reproduce this, clone the pm-graph repository [2], use `sudo
> ./bootgraph.py -f -fstat -maxdepth 10 -manual` to see what to add to
> `/boot/grub/grub.cfg`. Then reboot, and execute `sudo ./bootgraph.py -f
> -fstat -maxdepth 10`.
>
> If your system is powerful enough, you can use a higher maximum depth. I
> didn’t get around how `-cgfilter` works to get smaller HTML files.
>
>
> Kind regards,
>
> Paul
>
>
> [1] https://01.org/suspendresume
> [2] https://github.com/01org/pm-graph

Re: efisubsys_init takes more than a few milliseconds

[Paul Menzel]

Dear Ard,


Thank you for the quick reply.


On 03/24/2018 11:35 PM, Ard Biesheuvel wrote:

> On 24 March 2018 at 22:10, Paul Menzel <pmenzel+linux-efi@molgen.mpg.de> wrote:
>> Dear Ard,
>>
>>
>> According to `initcall_debug`, `efisubsys_init` takes more than a few
>> milliseconds to execute on a Dell XPS 13 9370 (Intel(R) Core(TM) i7-8550U
>> CPU @ 1.80GHz).
>>
>>> ```
>>> […]
>>> [ 0.144474] calling  efisubsys_init+0x0/0x2cf @ 1
>>> [ 0.144474] Registered efivars operations
>>> [ 0.173690] initcall efisubsys_init+0x0/0x2cf returned 0 after 27343 usecs
>>> […]
>>> ```
>>
>>
>> To get a vanilla Linux kernel to boot in well under one second, it’d be nice
>> if the time could be improved. Do you know, why it takes so long?
>>
>> According to `bootgraph.py` from pm-graph [1][2] it takes even a little
>> longer.
>>
>>> efisubsys_init: start=690.841, end=720.493, length(w/o overhead)=31.250
>>> ms, return=0
>>
>> There are several dozen calls to `virt_efi_get_next_variable()` all but one
>> taking around 0.335 ms. This path needs to be optimized. Is that possible?
> 
> That depends. These are firmware calls, so to make these calls faster,
> you need to modify the firmware, not the kernel.

Yeah, unfortunately, no free firmware runs on this laptop, and Dell 
doesn’t respond to these kind of reports, as they think, it’s not important.

> We may be able to make more intrusive changes to get rid of this
> delay, e.g., spin up a special kernel thread, but I'd have to check in
> more detail.

That’d be great.

> In the mean time, you can try passing 'efi=noruntime' to the kernel.

Thank you, I didn’t know about that. Unfortunately, initcall_debug still 
reports the same time although the one message is gone.

```
$ sudo dmesg | grep efisubsys
[    0.145779] calling  efisubsys_init+0x0/0x2cf @ 1
[    0.172034] initcall efisubsys_init+0x0/0x2cf returned 0 after 27343 
usecs
```

>> To reproduce this, clone the pm-graph repository [2], use `sudo
>> ./bootgraph.py -f -fstat -maxdepth 10 -manual` to see what to add to
>> `/boot/grub/grub.cfg`. Then reboot, and execute `sudo ./bootgraph.py -f
>> -fstat -maxdepth 10`.
>>
>> If your system is powerful enough, you can use a higher maximum depth. I
>> didn’t get around how `-cgfilter` works to get smaller HTML files.


Kind regards,

Paul


>> [1] https://01.org/suspendresume
>> [2] https://github.com/01org/pm-graph

Re: efisubsys_init takes more than a few milliseconds

[Paul Menzel]

Dear Ard,


On 03/25/2018 09:41 AM, Paul Menzel wrote:

> On 03/24/2018 11:35 PM, Ard Biesheuvel wrote:
> 
>> On 24 March 2018 at 22:10, Paul Menzel wrote:

>>> According to `initcall_debug`, `efisubsys_init` takes more than a few
>>> milliseconds to execute on a Dell XPS 13 9370 (Intel(R) Core(TM) 
>>> i7-8550U CPU @ 1.80GHz).
>>>
>>>> ```
>>>> […]
>>>> [ 0.144474] calling  efisubsys_init+0x0/0x2cf @ 1
>>>> [ 0.144474] Registered efivars operations
>>>> [ 0.173690] initcall efisubsys_init+0x0/0x2cf returned 0 after 27343 
>>>> usecs
>>>> […]
>>>> ```
>>>
>>>
>>> To get a vanilla Linux kernel to boot in well under one second, it’d 
>>> be nice
>>> if the time could be improved. Do you know, why it takes so long?
>>>
>>> According to `bootgraph.py` from pm-graph [1][2] it takes even a little
>>> longer.
>>>
>>>> efisubsys_init: start=690.841, end=720.493, length(w/o overhead)=31.250
>>>> ms, return=0
>>>
>>> There are several dozen calls to `virt_efi_get_next_variable()` all 
>>> but one
>>> taking around 0.335 ms. This path needs to be optimized. Is that 
>>> possible?
>>
>> That depends. These are firmware calls, so to make these calls faster,
>> you need to modify the firmware, not the kernel.
> 
> Yeah, unfortunately, no free firmware runs on this laptop, and Dell 
> doesn’t respond to these kind of reports, as they think, it’s not 
> important.
> 
>> We may be able to make more intrusive changes to get rid of this
>> delay, e.g., spin up a special kernel thread, but I'd have to check in
>> more detail.
> 
> That’d be great.
> 
>> In the mean time, you can try passing 'efi=noruntime' to the kernel.
> 
> Thank you, I didn’t know about that. Unfortunately, initcall_debug still 
> reports the same time although the one message is gone.
> 
> ```
> $ sudo dmesg | grep efisubsys
> [    0.145779] calling  efisubsys_init+0x0/0x2cf @ 1
> [    0.172034] initcall efisubsys_init+0x0/0x2cf returned 0 after 27343 usecs
> ```

Hmm, it looks like, I only edited `/etc/default/grub` and didn’t run 
`sudo update-grub`.

```
$ sudo dmesg | grep efisubsys
[    0.776339] calling  efisubsys_init+0x0/0x2cf @ 1
[    0.776339] initcall efisubsys_init+0x0/0x2cf returned 0 after 0 usecs
```

>>> To reproduce this, clone the pm-graph repository [2], use `sudo
>>> ./bootgraph.py -f -fstat -maxdepth 10 -manual` to see what to add to
>>> `/boot/grub/grub.cfg`. Then reboot, and execute `sudo ./bootgraph.py -f
>>> -fstat -maxdepth 10`.
>>>
>>> If your system is powerful enough, you can use a higher maximum depth. I
>>> didn’t get around how `-cgfilter` works to get smaller HTML files.


Kind regards,

Paul


>>> [1] https://01.org/suspendresume
>>> [2] https://github.com/01org/pm-graph

Re: efisubsys_init takes more than a few milliseconds

[Ard Biesheuvel]

On 25 March 2018 at 16:21, Paul Menzel <pmenzel+linux-efi@molgen.mpg.de> wrote:
> Dear Ard,
>
>
> On 03/25/2018 09:41 AM, Paul Menzel wrote:
>
>> On 03/24/2018 11:35 PM, Ard Biesheuvel wrote:
>>
>>> On 24 March 2018 at 22:10, Paul Menzel wrote:
>
>
>>>> According to `initcall_debug`, `efisubsys_init` takes more than a few
>>>> milliseconds to execute on a Dell XPS 13 9370 (Intel(R) Core(TM)
>>>> i7-8550U CPU @ 1.80GHz).
>>>>
>>>>> ```
>>>>> […]
>>>>> [ 0.144474] calling  efisubsys_init+0x0/0x2cf @ 1
>>>>> [ 0.144474] Registered efivars operations
>>>>> [ 0.173690] initcall efisubsys_init+0x0/0x2cf returned 0 after 27343
>>>>> usecs
>>>>> […]
>>>>> ```
>>>>
>>>>
>>>>
>>>> To get a vanilla Linux kernel to boot in well under one second, it’d be
>>>> nice
>>>> if the time could be improved. Do you know, why it takes so long?
>>>>
>>>> According to `bootgraph.py` from pm-graph [1][2] it takes even a little
>>>> longer.
>>>>
>>>>> efisubsys_init: start=690.841, end=720.493, length(w/o overhead)=31.250
>>>>> ms, return=0
>>>>
>>>>
>>>> There are several dozen calls to `virt_efi_get_next_variable()` all but
>>>> one
>>>> taking around 0.335 ms. This path needs to be optimized. Is that
>>>> possible?
>>>
>>>
>>> That depends. These are firmware calls, so to make these calls faster,
>>> you need to modify the firmware, not the kernel.
>>
>>
>> Yeah, unfortunately, no free firmware runs on this laptop, and Dell
>> doesn’t respond to these kind of reports, as they think, it’s not important.
>>
>>> We may be able to make more intrusive changes to get rid of this
>>> delay, e.g., spin up a special kernel thread, but I'd have to check in
>>> more detail.
>>
>>
>> That’d be great.
>>
>>> In the mean time, you can try passing 'efi=noruntime' to the kernel.
>>
>>
>> Thank you, I didn’t know about that. Unfortunately, initcall_debug still
>> reports the same time although the one message is gone.
>>
>> ```
>> $ sudo dmesg | grep efisubsys
>> [    0.145779] calling  efisubsys_init+0x0/0x2cf @ 1
>> [    0.172034] initcall efisubsys_init+0x0/0x2cf returned 0 after 27343
>> usecs
>> ```
>
>
> Hmm, it looks like, I only edited `/etc/default/grub` and didn’t run `sudo
> update-grub`.
>
> ```
> $ sudo dmesg | grep efisubsys
> [ 0.776339] calling  efisubsys_init+0x0/0x2cf @ 1
> [ 0.776339] initcall efisubsys_init+0x0/0x2cf returned 0 after 0 usecs
>
> ```
>

Excellent! If you want it any faster than that, I can't really help you :-)

Re: efisubsys_init takes more than a few milliseconds

[Paul Menzel]

[-- Attachment #1: Type: text/plain, Size: 2675 bytes --]

Dear Ard,


On 03/25/18 17:21, Paul Menzel wrote:

> On 03/25/2018 09:41 AM, Paul Menzel wrote:
> 
>> On 03/24/2018 11:35 PM, Ard Biesheuvel wrote:
>>
>>> On 24 March 2018 at 22:10, Paul Menzel wrote:
> 
>>>> According to `initcall_debug`, `efisubsys_init` takes more than a few
>>>> milliseconds to execute on a Dell XPS 13 9370 (Intel(R) Core(TM) i7-8550U CPU @ 1.80GHz).
>>>>
>>>>> ```
>>>>> […]
>>>>> [ 0.144474] calling  efisubsys_init+0x0/0x2cf @ 1
>>>>> [ 0.144474] Registered efivars operations
>>>>> [ 0.173690] initcall efisubsys_init+0x0/0x2cf returned 0 after 27343 usecs
>>>>> […]
>>>>> ```
>>>>
>>>>
>>>> To get a vanilla Linux kernel to boot in well under one second, it’d be nice
>>>> if the time could be improved. Do you know, why it takes so long?
>>>>
>>>> According to `bootgraph.py` from pm-graph [1][2] it takes even a little
>>>> longer.
>>>>
>>>>> efisubsys_init: start=690.841, end=720.493, length(w/o overhead)=31.250
>>>>> ms, return=0
>>>>
>>>> There are several dozen calls to `virt_efi_get_next_variable()` all but one
>>>> taking around 0.335 ms. This path needs to be optimized. Is that possible?
>>>
>>> That depends. These are firmware calls, so to make these calls faster,
>>> you need to modify the firmware, not the kernel.
>>
>> Yeah, unfortunately, no free firmware runs on this laptop, and Dell doesn’t respond to these kind of reports, as they think, it’s not important.
>>
>>> We may be able to make more intrusive changes to get rid of this
>>> delay, e.g., spin up a special kernel thread, but I'd have to check in
>>> more detail.
>>
>> That’d be great.

On the MSI B350M MORTAR (MS-7A37) it takes even longer, almost 50 ms.

```
[    0.204009] calling  efisubsys_init+0x0/0x30a @ 1
[    0.204009] Registered efivars operations
[    0.252262] initcall efisubsys_init+0x0/0x30a returned 0 after 46875 usecs
```

If a solution could be found to move this out of the hotpath, that’d be great.
But I am not sure, if threads can be used that early.

>>> In the mean time, you can try passing 'efi=noruntime' to the kernel.

[…]

>>>> To reproduce this, clone the pm-graph repository [2], use `sudo
>>>> ./bootgraph.py -f -fstat -maxdepth 10 -manual` to see what to add to
>>>> `/boot/grub/grub.cfg`. Then reboot, and execute `sudo ./bootgraph.py -f
>>>> -fstat -maxdepth 10`.
>>>>
>>>> If your system is powerful enough, you can use a higher maximum depth. I
>>>> didn’t get around how `-cgfilter` works to get smaller HTML files.


Kind regards,

Paul


>>>> [1] https://01.org/suspendresume
>>>> [2] https://github.com/01org/pm-graph


[-- Attachment #2: S/MIME Cryptographic Signature --]
[-- Type: application/pkcs7-signature, Size: 5174 bytes --]

Re: efisubsys_init takes more than a few milliseconds

[Ard Biesheuvel]

On 22 August 2018 at 15:18, Paul Menzel <pmenzel+linux-efi@molgen.mpg.de> wrote:
> Dear Ard,
>
>
> On 03/25/18 17:21, Paul Menzel wrote:
>
>> On 03/25/2018 09:41 AM, Paul Menzel wrote:
>>
>>> On 03/24/2018 11:35 PM, Ard Biesheuvel wrote:
>>>
>>>> On 24 March 2018 at 22:10, Paul Menzel wrote:
>>
>>>>> According to `initcall_debug`, `efisubsys_init` takes more than a few
>>>>> milliseconds to execute on a Dell XPS 13 9370 (Intel(R) Core(TM) i7-8550U CPU @ 1.80GHz).
>>>>>
>>>>>> ```
>>>>>> […]
>>>>>> [ 0.144474] calling  efisubsys_init+0x0/0x2cf @ 1
>>>>>> [ 0.144474] Registered efivars operations
>>>>>> [ 0.173690] initcall efisubsys_init+0x0/0x2cf returned 0 after 27343 usecs
>>>>>> […]
>>>>>> ```
>>>>>
>>>>>
>>>>> To get a vanilla Linux kernel to boot in well under one second, it’d be nice
>>>>> if the time could be improved. Do you know, why it takes so long?
>>>>>
>>>>> According to `bootgraph.py` from pm-graph [1][2] it takes even a little
>>>>> longer.
>>>>>
>>>>>> efisubsys_init: start=690.841, end=720.493, length(w/o overhead)=31.250
>>>>>> ms, return=0
>>>>>
>>>>> There are several dozen calls to `virt_efi_get_next_variable()` all but one
>>>>> taking around 0.335 ms. This path needs to be optimized. Is that possible?
>>>>
>>>> That depends. These are firmware calls, so to make these calls faster,
>>>> you need to modify the firmware, not the kernel.
>>>
>>> Yeah, unfortunately, no free firmware runs on this laptop, and Dell doesn’t respond to these kind of reports, as they think, it’s not important.
>>>
>>>> We may be able to make more intrusive changes to get rid of this
>>>> delay, e.g., spin up a special kernel thread, but I'd have to check in
>>>> more detail.
>>>
>>> That’d be great.
>
> On the MSI B350M MORTAR (MS-7A37) it takes even longer, almost 50 ms.
>
> ```
> [    0.204009] calling  efisubsys_init+0x0/0x30a @ 1
> [    0.204009] Registered efivars operations
> [    0.252262] initcall efisubsys_init+0x0/0x30a returned 0 after 46875 usecs
> ```
>
> If a solution could be found to move this out of the hotpath, that’d be great.
> But I am not sure, if threads can be used that early.
>

Could you narrow this down? Which call in efisubsys_init() is taking
up all this time?