* [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
@ 2024-11-27 23:35 Francesco Valla
2024-12-03 20:33 ` Bird, Tim
` (2 more replies)
0 siblings, 3 replies; 26+ messages in thread
From: Francesco Valla @ 2024-11-27 23:35 UTC (permalink / raw)
To: Linux Embedded
Dear fellow boot time optimizers,
following the first boot time SIG meeting, which I lurked with much pleasure
(but didn't participate to, as I was a bit in awe among such authorities), I'd
like to introduce myself with code rather than a presentation or resume.
Here is a python script which can analyze a dmesg output with initcall_debug
option enabled and extract some useful information. It can for example be used
to analyze the output of the grab-boot-data.sh tool that Tim presented on this
list [1] just a few days ago.
Usage is very simple, as the output of dmesg can be piped directly to it:
dmesg | analyze-initcall-debug.py
If no option is specified, it outputs a brief summary, like the following one
(obtained on my Beagleplay):
1758 drivers has been initialized, of which 1758 before userspace
119 probes happened outside of the init of their driver
0 deferred probes pending
---
Top 10 init/probes durations:
* 30200000.dss -> 523002us
* deferred_probe_initcall -> 487483us
* fd00000.gpu -> 162859us
* 8000f00.mdio -> 142521us
* 44043000.system-controller -> 71390us
* 2-004c -> 71178us
* 40900000.crypto -> 59350us
* 8000000.ethernet -> 58419us
* 44043000.system-controller:clock-controller -> 56599us
* jent_mod_init -> 52140us
A more complete output, reporting all durations as well as statuses, impact of
probe deferral and so on, can be produced either in HTML or Markdown format,
using respectively the --html or --markdown parameters.
Note: it hasn't (yet?) been used in a "production" environment, as I never
found the motivation to write a script and always analyzed manually the
initcall_debug output.
If you have time to take a look, please tell me what you think and what
can be added.
Thank you!
Regards,
Francesco
[1] https://lore.kernel.org/linux-embedded/MW5PR13MB5632F54DCBDA0C74370E531FFD5C2@MW5PR13MB5632.namprd13.prod.outlook.com/
--- analyze-initcall-debug.py script follows ---
#!/usr/bin/env python3
# -*- coding: utf-8 -*-
"""
This script can be used to analyze a Linux kernel dmesg output when the
initcall_debug command line output is used. It extract various information,
such as init durations, impact of probe deferral and so on.
"""
import argparse
import re
import sys
ERRCODE_PROBE_DEFER = 517
parser = argparse.ArgumentParser()
parser.add_argument('--dmesg', nargs='?', type=argparse.FileType('r'),
default=sys.stdin)
parser.add_argument('--html', action='store_true')
parser.add_argument('--markdown', action='store_true')
args = parser.parse_args()
class Run:
def __init__(self, start_time:int, end_time:int = -1, duration:int = 0, retval:int = 0):
self._start_time = start_time
self._end_time = end_time
self._duration = duration
self._retval = retval
self._ended = (end_time >= 0)
@property
def start_time(self) -> int:
return self._start_time
@property
def end_time(self) -> int:
return self._end_time
@end_time.setter
def end_time(self, time:int):
self._end_time = time
self._ended = True
@property
def duration(self) -> int:
return self._duration
@duration.setter
def duration(self, time:int):
self._duration = time
@property
def retval(self) -> int:
return self._retval
@retval.setter
def retval(self, val:int):
self._retval = val
@property
def running(self) -> bool:
return (not self._ended or abs(self.retval) == ERRCODE_PROBE_DEFER)
@property
def failed(self) -> bool:
return ((self.retval != 0) and not self.running)
class Entity:
def __init__(self, name:str, start_time:int = 0, end_time:int = 0, duration:int = 0, retval:int = 0):
self._name = name
self._runs = [ Run(start_time, end_time, duration, retval) ]
@property
def name(self) -> str:
return self._name
@property
def first_start_time(self) -> int:
return self._runs[0].start_time
@property
def last_start_time(self) -> int:
return self._runs[-1].start_time
@property
def first_end_time(self) -> int:
return self._runs[0].end_time
@property
def last_end_time(self) -> int:
return self._runs[-1].end_time
@property
def duration(self) -> int:
return sum([ r.duration for r in self._runs ])
@property
def wasted_time(self) -> int:
return sum([ r.duration for r in filter(lambda x: x.failed or abs(x.retval) == ERRCODE_PROBE_DEFER, self._runs) ])
@property
def retval(self) -> int:
return self._runs[-1].retval
@property
def failed(self) -> bool:
return self._runs[-1].failed
@property
def running(self) -> bool:
return self._runs[-1].running
@property
def deferred_probe_pending(self) -> bool:
return (abs(self._runs[-1].retval) == ERRCODE_PROBE_DEFER)
@property
def num_deferred_probes(self) -> int:
return len(list(filter(lambda r: abs(r.retval) == ERRCODE_PROBE_DEFER, self._runs)))
def addStart(self, start_time: int):
self._runs.append( Run(start_time) )
def addEnd(self, end_time:int = 0, duration:int = 0, retval:int = 0):
self._runs[-1].end_time = end_time
self._runs[-1].duration = duration
self._runs[-1].retval = retval
def addRun(self, start_time: int, end_time:int = 0, duration:int = 0, retval:int = 0):
self._runs.append( Run(start_time, end_time, duration, retval) )
class Driver (Entity):
def __init__(self, name: str, start_time: int):
super().__init__(name, start_time)
def addInit(self, init_time: int):
self.addStart(init_time)
def addReturn(self, return_time: int, duration: int, retval: int):
self.addEnd(return_time, duration, retval)
class Probe (Entity):
def __init__(self, name: str, return_time: int, duration: int, retval: int):
super().__init__(name, return_time, return_time, duration, retval)
class Init (Entity):
def __init__(self, name: str, start_time: int):
super().__init__(name, start_time)
# Regex for 'calling' messages
# "[ 0.466115] calling pci_sysfs_init+0x0/0xa8 @ 1"
calling_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] calling ([0-9a-zA-Z_]+)\+(0x[0-9a-fA-F]+\/0x[0-9a-fA-F]+) @ ([0-9]+)')
# Regex for 'initcall ... returned' messages
# "[ 0.466115] initcall pci_sysfs_init+0x0/0xa8 returned 0 after 5 usecs"
returned_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] initcall ([0-9a-zA-Z_]+)\+(0x[0-9a-fA-F]+\/0x[0-9a-fA-F]+) returned ([\-0-9]+) after ([0-9]+) usecs')
# Regex for 'probe ... returned' messages
# "[ 0.466115] probe of cpufreq-dt returned 517 after 140 usec"
probe_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] probe of ([0-9a-zA-Z_\-\.\:@]+) returned ([\-0-9]+) after ([0-9]+) usecs')
# Regex for
# "[ 1.060329] Run /sbin/init as init process"
init_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] Run ([/0-9a-zA-Z_]+) as init process')
drivers = list()
probes = list()
init = None
# Extract data from dmesg
for line in args.dmesg:
match = calling_prog.match(line)
if match is not None:
time = float(match.group(1)) * float(10^6)
name = str(match.group(2))
try:
time = float(match.group(1)) * float(10^6)
name = str(match.group(2))
except Exception as e:
print(f'Failed parsing line "{line.rstrip()}" as call')
raise e
else:
for d in filter(lambda x: x.name == name, drivers):
d.addInit(time)
break
else:
drivers.append(Driver(name, time))
finally:
continue
match = returned_prog.match(line)
if match is not None:
try:
time = float(match.group(1)) * float(10^6)
name = str(match.group(2))
retval = int(match.group(4))
duration = int(match.group(5))
except:
print(f'Failed parsing line "{line.rstrip()}" as call return')
else:
for d in filter(lambda x: x.name == name, drivers):
d.addReturn(time, duration, retval)
break
else:
print(f'Detected return for driver {name}, for which an init was never recorded')
finally:
continue
match = probe_prog.match(line)
if match is not None:
try:
time = float(match.group(1)) * float(10^6)
name = str(match.group(2))
retval = int(match.group(3))
duration = int(match.group(4))
except:
print(f'Failed parsing line "{line.rstrip()}" as probe return')
else:
for d in filter(lambda x: x.name == name, probes):
d.addRun(time, time, duration, retval)
break
else:
probes.append(Probe(name, time, duration, retval))
finally:
continue
if init is None:
match = init_prog.match(line)
if match is not None:
try:
time = float(match.group(1)) * float(10^6)
name = str(match.group(2))
except:
print(f'Failed parsing line "{line.rstrip()}" as probe return')
else:
init = Init(name, time)
finally:
continue
if args.markdown:
print('| Name | Type [^1] | Status [^2] | Duration (us) | Before userspace | Num deferred probes | Time spent in failed inits (us) |')
print('| -----| --------- | ----------- | ------------- | ---------------- | ------------------- | ------------------------------- |')
for d in sorted(filter(lambda k: k.duration > 0, drivers + probes), key=lambda k: k.duration, reverse=True):
etype = 'I' if d in drivers else 'P'
run_status = 'D' if d.deferred_probe_pending else 'R' if d.running else f'F({abs(d.retval)})' if d.failed else 'K'
before_init = 'Y' if d.last_start_time < init.last_start_time else 'N'
print(f'| {d.name} | {etype} | {run_status} | {d.duration} | {before_init} | {d.num_deferred_probes} | {d.wasted_time} |')
print('[^1]: I=Init function, P=device Probe')
print('[^2]: D=Deferred probe pending, R=still Running, F(N)=Failed (with errcode N), K=init oK')
elif args.html:
print(
'''
<!DOCTYPE HTML>
<html>
<head>
<meta charset="utf-8" />
<title>Initcall analysis</title>
<meta name="viewport" content="width=device-width, initial-scale=1" />
<style>
table, th, td {
border: 1px solid;
}
</style>
</head>
<body>
<table>
<tr>
<th>Name</th>
<th>Type <a href="#note1">[1]</a></th>
<th>Status <a href="#note2">[2]</a></th>
<th>Duration (us)</th>
<th>Before userspace</th>
<th>Num deferred probes</th>
<th>Time spent in failed inits (us)</th>
</tr>''')
for d in sorted(filter(lambda k: k.duration > 0, drivers + probes), key=lambda k: k.duration, reverse=True):
etype = 'I' if d in drivers else 'P'
run_status = 'D' if d.deferred_probe_pending else 'R' if d.running else f'F({abs(d.retval)})' if d.failed else 'K'
before_init = 'Y' if d.last_start_time < init.last_start_time else 'N'
print(
f'''
<tr>
<td>{d.name}</td>
<td>{etype}</td>
<td>{run_status}</td>
<td>{d.duration}</td>
<td>{before_init}</td>
<td>{d.num_deferred_probes}</td>
<td>{d.wasted_time}</td>
</tr>''')
print(
'''
</table>
<p id="note1">[1] I=Init function, P=device Probe</p>
<p id="note2">[2] D=Deferred probe pending, R=still Running, F(N)=Failed (with errcode N), K=init oK</p>
</body>
</html>
''')
else:
print(f'{len(drivers)} drivers has been initialized, of which {len(list(filter(lambda d: d.last_start_time < init.last_start_time, drivers)))} before userspace')
print(f'{len(probes)} probes happened outside of the init of their driver')
print(f'{len(list(filter(lambda d: d.deferred_probe_pending, drivers + probes)))} deferred probes pending')
print('---')
print('Top 10 init/probes durations:')
for d in sorted(filter(lambda k: k.duration > 0, drivers + probes), key=lambda k: k.duration, reverse=True)[0:10]:
print(f' * {d.name} -> {d.duration}us')
^ permalink raw reply [flat|nested] 26+ messages in thread
* RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-11-27 23:35 [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Francesco Valla
@ 2024-12-03 20:33 ` Bird, Tim
2024-12-05 12:57 ` Francesco Valla
2024-12-03 21:24 ` [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Bird, Tim
2024-12-04 0:29 ` Bird, Tim
2 siblings, 1 reply; 26+ messages in thread
From: Bird, Tim @ 2024-12-03 20:33 UTC (permalink / raw)
To: Francesco Valla, Linux Embedded
Hey Francesco,
I appreciate the new tool, and have some feedback below.
I'll separate my response and ideas into 2 categories:
- issues raised from your sample report
- feedback on the tool itself
and send them as separate emails.
> -----Original Message-----
> From: Francesco Valla <francesco@valla.it>
> Dear fellow boot time optimizers,
>
> following the first boot time SIG meeting, which I lurked with much pleasure
> (but didn't participate to, as I was a bit in awe among such authorities), I'd
> like to introduce myself with code rather than a presentation or resume.
>
> Here is a python script which can analyze a dmesg output with initcall_debug
> option enabled and extract some useful information. It can for example be used
> to analyze the output of the grab-boot-data.sh tool that Tim presented on this
> list [1] just a few days ago.
>
> Usage is very simple, as the output of dmesg can be piped directly to it:
>
> dmesg | analyze-initcall-debug.py
>
> If no option is specified, it outputs a brief summary, like the following one
> (obtained on my Beagleplay):
>
> 1758 drivers has been initialized, of which 1758 before userspace
> 119 probes happened outside of the init of their driver
> 0 deferred probes pending
> ---
> Top 10 init/probes durations:
> * 30200000.dss -> 523002us
This call, and a lot of the others are missing function names. Did you compile the kernel with
CONFIG_KALLSYMS=y?
If that's the case, is there a way to use the System.map file for the kernel (used on
the machine where the dmesg was obtained from) to map these addresses
to their respective function names?
> * deferred_probe_initcall -> 487483us
I feel like this function is interfering with the ability to correctly assign
boot time delays to the correct initcall.
I would really like to see someone tackle this issue, by studying the deferred_probe_initcall
function, to see if there's a way to instrument it so that the cost of each
probe can be reported and then associated with corresponding initcall, when initcall_debug
is used.
Does anyone want to look into this issue?
It falls under the category of improving instrumentation and reducing blind spots during
boot.
> * fd00000.gpu -> 162859us
> * 8000f00.mdio -> 142521us
> * 44043000.system-controller -> 71390us
> * 2-004c -> 71178us
> * 40900000.crypto -> 59350us
> * 8000000.ethernet -> 58419us
> * 44043000.system-controller:clock-controller -> 56599us
> * jent_mod_init -> 52140us
>
> A more complete output, reporting all durations as well as statuses, impact of
> probe deferral and so on, can be produced either in HTML or Markdown format,
> using respectively the --html or --markdown parameters.
This seems quite useful, as this will allow me to add this output to my boot-time
wiki quite easily.
>
> Note: it hasn't (yet?) been used in a "production" environment, as I never
> found the motivation to write a script and always analyzed manually the
> initcall_debug output.
>
> If you have time to take a look, please tell me what you think and what
> can be added.
I'll give feedback on the tool itself in a separate message.
-- Tim
>
> [1] https://lore.kernel.org/linux-
> embedded/MW5PR13MB5632F54DCBDA0C74370E531FFD5C2@MW5PR13MB5632.namprd13.prod.outlook.com/
>
^ permalink raw reply [flat|nested] 26+ messages in thread
* [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-11-27 23:35 [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Francesco Valla
2024-12-03 20:33 ` Bird, Tim
@ 2024-12-03 21:24 ` Bird, Tim
2024-12-05 7:02 ` Stephan Mueller
2024-12-30 22:22 ` [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Francesco Valla
2024-12-04 0:29 ` Bird, Tim
2 siblings, 2 replies; 26+ messages in thread
From: Bird, Tim @ 2024-12-03 21:24 UTC (permalink / raw)
To: Francesco Valla, Linux Embedded; +Cc: smueller@chronox.de
> -----Original Message-----
> From: Francesco Valla <francesco@valla.it>
> Dear fellow boot time optimizers,
>
> following the first boot time SIG meeting, which I lurked with much pleasure
> (but didn't participate to, as I was a bit in awe among such authorities), I'd
> like to introduce myself with code rather than a presentation or resume.
>
> Here is a python script which can analyze a dmesg output with initcall_debug
> option enabled and extract some useful information. It can for example be used
> to analyze the output of the grab-boot-data.sh tool that Tim presented on this
> list [1] just a few days ago.
>
> Usage is very simple, as the output of dmesg can be piped directly to it:
>
> dmesg | analyze-initcall-debug.py
>
> If no option is specified, it outputs a brief summary, like the following one
> (obtained on my Beagleplay):
>
> 1758 drivers has been initialized, of which 1758 before userspace
> 119 probes happened outside of the init of their driver
> 0 deferred probes pending
> ---
> Top 10 init/probes durations:
> * 30200000.dss -> 523002us
> * deferred_probe_initcall -> 487483us
> * fd00000.gpu -> 162859us
> * 8000f00.mdio -> 142521us
> * 44043000.system-controller -> 71390us
> * 2-004c -> 71178us
> * 40900000.crypto -> 59350us
> * 8000000.ethernet -> 58419us
> * 44043000.system-controller:clock-controller -> 56599us
> * jent_mod_init -> 52140us
This is odd. On my beagleplay board, jent_mod_init only took 32326us.
(see https://birdcloud.org/boot-time-files/boot-data-timslab-bp1-241203-134136.txt)
I'm assuming that we have similar hardware, but possibly different configs,
kernel cmdlines or kernel versions. I'll take a look at this and see if I can
figure out what the difference is between our systems, that causes the
difference in the duration for this function.
This initcall (jent_mod_init) is on my list of initcalls to research to see if they
can be improved or deferred. I haven't seen any degradation in system
behavior by deferring this initcall on my system, but that could be from
lack of my system doing some related operation that needs the RNG data, or my
own ignorance of the effects of this call.
Can someone comment on what items or operations might depend on jent_mod_init
in early boot? In particular, would we expect any cryptographic problems if
the initcall was deferred to a few seconds after booting?
It can be configured as a module, which makes me think that maybe loading
it sometime in very late boot (or even later) is OK.
jent_mod_init is defined in crypto/jitterentropy-kcapi.c, and controlled by
CONFIG_CRYPTO_JITTERENTROPY (See crypto/Kconfig)
It appears to do some random number generator seeding by measuring
the jitter of a compressiong operation in the kernel. I assume some of the cryptography
configs affect the duration of the operations. The initcall duration results on
my beagleplay seem to be relatively consistent (in the 32ms range consistently),
and from bobs_lab, on machine sam1, the duration range is also consistent
(at between 4800 and 5200 usecs).
I'd be interested to see if the range is consistent between runs on other machines
Francesco - Can you submit another boot-data file (or 2 or 3) for francsecoslab-beagleplay, to
provide some data on this?
Also, can anyone else who sees this initcall in their boot sequence run grab-boot-data.sh
(from https://birdcloud.org/boot-time/Boot-time_Tools)
and submit the data for one or more of their machines?
Stephan Mueller - what are you seeing for the cost of this operation on your machines?
This is one of the first initcalls I'm going to dive into to see if it can be improved or deferred.
Maybe some of the RNG seeding can be held over from a previous boot, in order to
eliminate the overhead on the early portion of a current boot. Any feedback on that
idea?
Thanks.
-- Tim
^ permalink raw reply [flat|nested] 26+ messages in thread
* RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-11-27 23:35 [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Francesco Valla
2024-12-03 20:33 ` Bird, Tim
2024-12-03 21:24 ` [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Bird, Tim
@ 2024-12-04 0:29 ` Bird, Tim
2024-12-05 13:05 ` Francesco Valla
2 siblings, 1 reply; 26+ messages in thread
From: Bird, Tim @ 2024-12-04 0:29 UTC (permalink / raw)
To: Francesco Valla, Linux Embedded
> -----Original Message-----
> From: Francesco Valla <francesco@valla.it>
> Dear fellow boot time optimizers,
>
> following the first boot time SIG meeting, which I lurked with much pleasure
> (but didn't participate to, as I was a bit in awe among such authorities), I'd
> like to introduce myself with code rather than a presentation or resume.
>
> Here is a python script which can analyze a dmesg output with initcall_debug
> option enabled and extract some useful information. It can for example be used
> to analyze the output of the grab-boot-data.sh tool that Tim presented on this
> list [1] just a few days ago.
>
> Usage is very simple, as the output of dmesg can be piped directly to it:
>
> dmesg | analyze-initcall-debug.py
>
> If no option is specified, it outputs a brief summary, like the following one
> (obtained on my Beagleplay):
>
> 1758 drivers has been initialized, of which 1758 before userspace
> 119 probes happened outside of the init of their driver
> 0 deferred probes pending
> ---
> Top 10 init/probes durations:
> * 30200000.dss -> 523002us
> * deferred_probe_initcall -> 487483us
> * fd00000.gpu -> 162859us
> * 8000f00.mdio -> 142521us
> * 44043000.system-controller -> 71390us
> * 2-004c -> 71178us
> * 40900000.crypto -> 59350us
> * 8000000.ethernet -> 58419us
> * 44043000.system-controller:clock-controller -> 56599us
> * jent_mod_init -> 52140us
>
> A more complete output, reporting all durations as well as statuses, impact of
> probe deferral and so on, can be produced either in HTML or Markdown format,
> using respectively the --html or --markdown parameters.
>
> Note: it hasn't (yet?) been used in a "production" environment, as I never
> found the motivation to write a script and always analyzed manually the
> initcall_debug output.
>
> If you have time to take a look, please tell me what you think and what
> can be added.
>
> Thank you!
>
> Regards,
> Francesco
>
> [1] https://lore.kernel.org/linux-
> embedded/MW5PR13MB5632F54DCBDA0C74370E531FFD5C2@MW5PR13MB5632.namprd13.prod.outlook.com/
>
> --- analyze-initcall-debug.py script follows ---
>
> #!/usr/bin/env python3
> # -*- coding: utf-8 -*-
>
> """
> This script can be used to analyze a Linux kernel dmesg output when the
> initcall_debug command line output is used. It extract various information,
> such as init durations, impact of probe deferral and so on.
> """
>
> import argparse
> import re
> import sys
>
> ERRCODE_PROBE_DEFER = 517
>
> parser = argparse.ArgumentParser()
>
> parser.add_argument('--dmesg', nargs='?', type=argparse.FileType('r'),
> default=sys.stdin)
> parser.add_argument('--html', action='store_true')
> parser.add_argument('--markdown', action='store_true')
> args = parser.parse_args()
>
> class Run:
> def __init__(self, start_time:int, end_time:int = -1, duration:int = 0, retval:int = 0):
> self._start_time = start_time
> self._end_time = end_time
> self._duration = duration
> self._retval = retval
> self._ended = (end_time >= 0)
>
> @property
> def start_time(self) -> int:
> return self._start_time
>
> @property
> def end_time(self) -> int:
> return self._end_time
>
> @end_time.setter
> def end_time(self, time:int):
> self._end_time = time
> self._ended = True
>
> @property
> def duration(self) -> int:
> return self._duration
>
> @duration.setter
> def duration(self, time:int):
> self._duration = time
>
> @property
> def retval(self) -> int:
> return self._retval
>
> @retval.setter
> def retval(self, val:int):
> self._retval = val
>
> @property
> def running(self) -> bool:
> return (not self._ended or abs(self.retval) == ERRCODE_PROBE_DEFER)
>
> @property
> def failed(self) -> bool:
> return ((self.retval != 0) and not self.running)
>
>
> class Entity:
> def __init__(self, name:str, start_time:int = 0, end_time:int = 0, duration:int = 0, retval:int = 0):
> self._name = name
> self._runs = [ Run(start_time, end_time, duration, retval) ]
>
> @property
> def name(self) -> str:
> return self._name
>
> @property
> def first_start_time(self) -> int:
> return self._runs[0].start_time
>
> @property
> def last_start_time(self) -> int:
> return self._runs[-1].start_time
>
> @property
> def first_end_time(self) -> int:
> return self._runs[0].end_time
>
> @property
> def last_end_time(self) -> int:
> return self._runs[-1].end_time
>
> @property
> def duration(self) -> int:
> return sum([ r.duration for r in self._runs ])
>
> @property
> def wasted_time(self) -> int:
> return sum([ r.duration for r in filter(lambda x: x.failed or abs(x.retval) == ERRCODE_PROBE_DEFER, self._runs) ])
>
> @property
> def retval(self) -> int:
> return self._runs[-1].retval
>
> @property
> def failed(self) -> bool:
> return self._runs[-1].failed
>
> @property
> def running(self) -> bool:
> return self._runs[-1].running
>
> @property
> def deferred_probe_pending(self) -> bool:
> return (abs(self._runs[-1].retval) == ERRCODE_PROBE_DEFER)
>
> @property
> def num_deferred_probes(self) -> int:
> return len(list(filter(lambda r: abs(r.retval) == ERRCODE_PROBE_DEFER, self._runs)))
>
> def addStart(self, start_time: int):
> self._runs.append( Run(start_time) )
>
> def addEnd(self, end_time:int = 0, duration:int = 0, retval:int = 0):
> self._runs[-1].end_time = end_time
> self._runs[-1].duration = duration
> self._runs[-1].retval = retval
>
> def addRun(self, start_time: int, end_time:int = 0, duration:int = 0, retval:int = 0):
> self._runs.append( Run(start_time, end_time, duration, retval) )
>
>
> class Driver (Entity):
> def __init__(self, name: str, start_time: int):
> super().__init__(name, start_time)
>
> def addInit(self, init_time: int):
> self.addStart(init_time)
>
> def addReturn(self, return_time: int, duration: int, retval: int):
> self.addEnd(return_time, duration, retval)
>
>
> class Probe (Entity):
> def __init__(self, name: str, return_time: int, duration: int, retval: int):
> super().__init__(name, return_time, return_time, duration, retval)
>
>
> class Init (Entity):
> def __init__(self, name: str, start_time: int):
> super().__init__(name, start_time)
>
>
> # Regex for 'calling' messages
> # "[ 0.466115] calling pci_sysfs_init+0x0/0xa8 @ 1"
> calling_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] calling ([0-9a-zA-Z_]+)\+(0x[0-9a-fA-F]+\/0x[0-9a-fA-F]+) @ ([0-9]+)')
>
> # Regex for 'initcall ... returned' messages
> # "[ 0.466115] initcall pci_sysfs_init+0x0/0xa8 returned 0 after 5 usecs"
> returned_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] initcall ([0-9a-zA-Z_]+)\+(0x[0-9a-fA-F]+\/0x[0-9a-fA-F]+) returned ([\-0-9]+) after ([0-
> 9]+) usecs')
>
> # Regex for 'probe ... returned' messages
> # "[ 0.466115] probe of cpufreq-dt returned 517 after 140 usec"
> probe_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] probe of ([0-9a-zA-Z_\-\.\:@]+) returned ([\-0-9]+) after ([0-9]+) usecs')
>
> # Regex for
> # "[ 1.060329] Run /sbin/init as init process"
> init_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] Run ([/0-9a-zA-Z_]+) as init process')
>
I'm a little worried about the fragility of these regex lines. If a dmesg line doesn't
match, then it is silently ignored. It might be worth checking for a simpler match first,
then trying for the full regex match. See below.
> drivers = list()
> probes = list()
> init = None
>
> # Extract data from dmesg
> for line in args.dmesg:
It might be nice to keep track of the line number here, for more detail
when reporting parsing errors.
> match = calling_prog.match(line)
if "] calling" in line:
match = calling_prog.match(line)
> if match is not None:
if match:
is better here, IMHO.
> time = float(match.group(1)) * float(10^6)
> name = str(match.group(2))
> try:
> time = float(match.group(1)) * float(10^6)
> name = str(match.group(2))
> except Exception as e:
> print(f'Failed parsing line "{line.rstrip()}" as call')
> raise e
> else:
> for d in filter(lambda x: x.name == name, drivers):
This is a bit strange.
Why not use a dictionary for drivers here, with name as the key, instead
of a list where you have to do a search?
> d.addInit(time)
> break
> else:
> drivers.append(Driver(name, time))
If the driver names are unique, then this can be:
drivers[name] = Driver(name, time)
Otherwise:
drivers[name] = drivers.get(name, []).append(Drivers(name, time))
which is equivalent to:
if name in drivers:
drivers[name].append(Driver(name, time))
else:
drivers[name] = [Drivers(name, time)]
> finally:
> continue
>
> match = returned_prog.match(line)
> if match is not None:
if match:
> try:
> time = float(match.group(1)) * float(10^6)
> name = str(match.group(2))
> retval = int(match.group(4))
> duration = int(match.group(5))
> except:
> print(f'Failed parsing line "{line.rstrip()}" as call return')
> else:
> for d in filter(lambda x: x.name == name, drivers):
Same thing here - should use a dictionary with name as key.
> d.addReturn(time, duration, retval)
> break
> else:
> print(f'Detected return for driver {name}, for which an init was never recorded')
> finally:
> continue
>
> match = probe_prog.match(line)
> if match is not None:
if match:
> try:
> time = float(match.group(1)) * float(10^6)
> name = str(match.group(2))
> retval = int(match.group(3))
> duration = int(match.group(4))
> except:
> print(f'Failed parsing line "{line.rstrip()}" as probe return')
> else:
> for d in filter(lambda x: x.name == name, probes):
Should use a dictionary here.
> d.addRun(time, time, duration, retval)
> break
> else:
> probes.append(Probe(name, time, duration, retval))
> finally:
> continue
>
> if init is None:
if not init:
> match = init_prog.match(line)
> if match is not None:
if match:
> try:
> time = float(match.group(1)) * float(10^6)
> name = str(match.group(2))
> except:
> print(f'Failed parsing line "{line.rstrip()}" as probe return')
> else:
> init = Init(name, time)
> finally:
> continue
>
> if args.markdown:
> print('| Name | Type [^1] | Status [^2] | Duration (us) | Before userspace | Num deferred probes | Time spent in failed inits (us) |')
> print('| -----| --------- | ----------- | ------------- | ---------------- | ------------------- | ------------------------------- |')
> for d in sorted(filter(lambda k: k.duration > 0, drivers + probes), key=lambda k: k.duration, reverse=True):
> etype = 'I' if d in drivers else 'P'
> run_status = 'D' if d.deferred_probe_pending else 'R' if d.running else f'F({abs(d.retval)})' if d.failed else 'K'
> before_init = 'Y' if d.last_start_time < init.last_start_time else 'N'
> print(f'| {d.name} | {etype} | {run_status} | {d.duration} | {before_init} | {d.num_deferred_probes} | {d.wasted_time} |')
> print('[^1]: I=Init function, P=device Probe')
> print('[^2]: D=Deferred probe pending, R=still Running, F(N)=Failed (with errcode N), K=init oK')
> elif args.html:
> print(
> '''
> <!DOCTYPE HTML>
> <html>
> <head>
> <meta charset="utf-8" />
> <title>Initcall analysis</title>
> <meta name="viewport" content="width=device-width, initial-scale=1" />
> <style>
> table, th, td {
> border: 1px solid;
> }
> </style>
> </head>
> <body>
>
I'd like a version of this where it just emits the HTML for the body, and not the full
page. I could use this in my birdcloud boot-time wiki.
Maybe add an option to select full HTML page vs HTML snippet?
> <table>
> <tr>
> <th>Name</th>
> <th>Type <a href="#note1">[1]</a></th>
> <th>Status <a href="#note2">[2]</a></th>
> <th>Duration (us)</th>
> <th>Before userspace</th>
> <th>Num deferred probes</th>
> <th>Time spent in failed inits (us)</th>
> </tr>''')
>
> for d in sorted(filter(lambda k: k.duration > 0, drivers + probes), key=lambda k: k.duration, reverse=True):
> etype = 'I' if d in drivers else 'P'
> run_status = 'D' if d.deferred_probe_pending else 'R' if d.running else f'F({abs(d.retval)})' if d.failed else 'K'
> before_init = 'Y' if d.last_start_time < init.last_start_time else 'N'
> print(
> f'''
> <tr>
> <td>{d.name}</td>
> <td>{etype}</td>
> <td>{run_status}</td>
> <td>{d.duration}</td>
> <td>{before_init}</td>
> <td>{d.num_deferred_probes}</td>
> <td>{d.wasted_time}</td>
> </tr>''')
>
> print(
> '''
> </table>
> <p id="note1">[1] I=Init function, P=device Probe</p>
> <p id="note2">[2] D=Deferred probe pending, R=still Running, F(N)=Failed (with errcode N), K=init oK</p>
> </body>
> </html>
> ''')
>
> else:
> print(f'{len(drivers)} drivers has been initialized, of which {len(list(filter(lambda d: d.last_start_time < init.last_start_time, drivers)))}
> before userspace')
> print(f'{len(probes)} probes happened outside of the init of their driver')
>
> print(f'{len(list(filter(lambda d: d.deferred_probe_pending, drivers + probes)))} deferred probes pending')
>
> print('---')
>
> print('Top 10 init/probes durations:')
> for d in sorted(filter(lambda k: k.duration > 0, drivers + probes), key=lambda k: k.duration, reverse=True)[0:10]:
> print(f' * {d.name} -> {d.duration}us')
>
>
>
>
Just my 2 cents...
-- Tim
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-12-03 21:24 ` [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Bird, Tim
@ 2024-12-05 7:02 ` Stephan Mueller
[not found] ` <CAORPcfUfgNnQb6m0baW9qEGnrGYsnbpvwUUmF5Y9Byh9_iMAZw@mail.gmail.com>
2024-12-30 22:22 ` [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Francesco Valla
1 sibling, 1 reply; 26+ messages in thread
From: Stephan Mueller @ 2024-12-05 7:02 UTC (permalink / raw)
To: Francesco Valla, Linux Embedded, Bird, Tim
Am Dienstag, 3. Dezember 2024, 22:24:28 Mitteleuropäische Normalzeit schrieb
Bird, Tim:
Hi Tim,
> > -----Original Message-----
> > From: Francesco Valla <francesco@valla.it>
> > Dear fellow boot time optimizers,
> >
> > following the first boot time SIG meeting, which I lurked with much
> > pleasure
(but didn't participate to, as I was a bit in awe among such
> > authorities), I'd like to introduce myself with code rather than a
> > presentation or resume.
> > Here is a python script which can analyze a dmesg output with
> > initcall_debug
option enabled and extract some useful information. It
> > can for example be used to analyze the output of the grab-boot-data.sh
> > tool that Tim presented on this list [1] just a few days ago.
> >
> > Usage is very simple, as the output of dmesg can be piped directly to it:
> >
> >
> > dmesg | analyze-initcall-debug.py
> >
> >
> > If no option is specified, it outputs a brief summary, like the following
> > one
(obtained on my Beagleplay):
> >
> > 1758 drivers has been initialized, of which 1758 before userspace
> > 119 probes happened outside of the init of their driver
> > 0 deferred probes pending
> > ---
> > Top 10 init/probes durations:
> >
> > * 30200000.dss -> 523002us
> > * deferred_probe_initcall -> 487483us
> > * fd00000.gpu -> 162859us
> > * 8000f00.mdio -> 142521us
> > * 44043000.system-controller -> 71390us
> > * 2-004c -> 71178us
> > * 40900000.crypto -> 59350us
> > * 8000000.ethernet -> 58419us
> > * 44043000.system-controller:clock-controller -> 56599us
> > * jent_mod_init -> 52140us
>
>
> This is odd. On my beagleplay board, jent_mod_init only took 32326us.
> (see
> https://birdcloud.org/boot-time-files/boot-data-timslab-bp1-241203-134136.t
> xt)
> I'm assuming that we have similar hardware, but possibly different configs,
> kernel cmdlines or kernel versions. I'll take a look at this and see if I
> can figure out what the difference is between our systems, that causes the
> difference in the duration for this function.
>
> This initcall (jent_mod_init) is on my list of initcalls to research to see
> if they
can be improved or deferred. I haven't seen any degradation in
> system behavior by deferring this initcall on my system, but that could be
> from lack of my system doing some related operation that needs the RNG
> data, or my own ignorance of the effects of this call.
>
> Can someone comment on what items or operations might depend on
> jent_mod_init
in early boot? In particular, would we expect any
> cryptographic problems if the initcall was deferred to a few seconds after
> booting?
>
> It can be configured as a module, which makes me think that maybe loading
> it sometime in very late boot (or even later) is OK.
>
> jent_mod_init is defined in crypto/jitterentropy-kcapi.c, and controlled by
>
CONFIG_CRYPTO_JITTERENTROPY (See crypto/Kconfig)
>
> It appears to do some random number generator seeding by measuring
> the jitter of a compressiong operation in the kernel. I assume some of the
> cryptography
configs affect the duration of the operations. The initcall
> duration results on my beagleplay seem to be relatively consistent (in the
> 32ms range consistently), and from bobs_lab, on machine sam1, the duration
> range is also consistent (at between 4800 and 5200 usecs).
>
> I'd be interested to see if the range is consistent between runs on other
> machines
> Francesco - Can you submit another boot-data file (or 2 or 3) for
> francsecoslab-beagleplay, to
provide some data on this?
>
> Also, can anyone else who sees this initcall in their boot sequence run
> grab-boot-data.sh
(from https://birdcloud.org/boot-time/Boot-time_Tools)
> and submit the data for one or more of their machines?
>
> Stephan Mueller - what are you seeing for the cost of this operation on your
> machines?
I have never done the measurements on my system, but with patch
95a798d20060d2b648dd604321e347c85edfd783 the so-called oversampling rate was
changed which reduced the performance of the Jitter RNG (read: it takes a bit
more to gather all data).
> This is one of the first initcalls I'm going to dive into to see if it can
> be improved or deferred.
Maybe some of the RNG seeding can be held over
> from a previous boot, in order to eliminate the overhead on the early
> portion of a current boot. Any feedback on that idea?
>
> Thanks.
> -- Tim
>
Ciao
Stephan
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-12-03 20:33 ` Bird, Tim
@ 2024-12-05 12:57 ` Francesco Valla
2024-12-05 14:58 ` Geert Uytterhoeven
2024-12-09 3:10 ` [RFC PATCH] boot-time: instrument probes more Bird, Tim
0 siblings, 2 replies; 26+ messages in thread
From: Francesco Valla @ 2024-12-05 12:57 UTC (permalink / raw)
To: Linux Embedded, Bird, Tim
Hi Tim,
thank you for taking the time to review the tool. My reply too will be splitted in two parts.
On Tuesday, 3 December 2024 at 21:33:06 Bird, Tim <Tim.Bird@sony.com> wrote:
> Hey Francesco,
>
> I appreciate the new tool, and have some feedback below.
>
> I'll separate my response and ideas into 2 categories:
> - issues raised from your sample report
> - feedback on the tool itself
>
> and send them as separate emails.
>
> > -----Original Message-----
> > From: Francesco Valla <francesco@valla.it>
> > Dear fellow boot time optimizers,
> >
> > following the first boot time SIG meeting, which I lurked with much pleasure
> > (but didn't participate to, as I was a bit in awe among such authorities), I'd
> > like to introduce myself with code rather than a presentation or resume.
> >
> > Here is a python script which can analyze a dmesg output with initcall_debug
> > option enabled and extract some useful information. It can for example be used
> > to analyze the output of the grab-boot-data.sh tool that Tim presented on this
> > list [1] just a few days ago.
> >
> > Usage is very simple, as the output of dmesg can be piped directly to it:
> >
> > dmesg | analyze-initcall-debug.py
> >
> > If no option is specified, it outputs a brief summary, like the following one
> > (obtained on my Beagleplay):
> >
> > 1758 drivers has been initialized, of which 1758 before userspace
> > 119 probes happened outside of the init of their driver
> > 0 deferred probes pending
> > ---
> > Top 10 init/probes durations:
> > * 30200000.dss -> 523002us
>
> This call, and a lot of the others are missing function names. Did you compile the kernel with
> CONFIG_KALLSYMS=y?
>
> If that's the case, is there a way to use the System.map file for the kernel (used on
> the machine where the dmesg was obtained from) to map these addresses
> to their respective function names?
>
These are not in fact addresses, but rather device names. In my understanding, they are printed
when a probe happens outside of the initialization function for their driver. I still don't have an idea
on how to match probes with their original initcall, in order to present the user the complete picture.
> > * deferred_probe_initcall -> 487483us
>
> I feel like this function is interfering with the ability to correctly assign
> boot time delays to the correct initcall.
>
> I would really like to see someone tackle this issue, by studying the deferred_probe_initcall
> function, to see if there's a way to instrument it so that the cost of each
> probe can be reported and then associated with corresponding initcall, when initcall_debug
> is used.
>
> Does anyone want to look into this issue?
I can take a look, but probably toward the end of the year. Another similar area I'd like to investigate
is related to initcall time vs actual probe time: for drivers instantiated multiple time, I'd like to know
how much time each probe took rather than the overall time.
Regards,
Francesco
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-12-04 0:29 ` Bird, Tim
@ 2024-12-05 13:05 ` Francesco Valla
0 siblings, 0 replies; 26+ messages in thread
From: Francesco Valla @ 2024-12-05 13:05 UTC (permalink / raw)
To: Linux Embedded, Bird, Tim
Hi Tim,
On Wednesday, 4 December 2024 at 01:29:18 Bird, Tim <Tim.Bird@sony.com> wrote:
>
> > -----Original Message-----
> > From: Francesco Valla <francesco@valla.it>
> > Dear fellow boot time optimizers,
> >
> > following the first boot time SIG meeting, which I lurked with much pleasure
> > (but didn't participate to, as I was a bit in awe among such authorities), I'd
> > like to introduce myself with code rather than a presentation or resume.
> >
> > Here is a python script which can analyze a dmesg output with initcall_debug
> > option enabled and extract some useful information. It can for example be used
> > to analyze the output of the grab-boot-data.sh tool that Tim presented on this
> > list [1] just a few days ago.
> >
> > Usage is very simple, as the output of dmesg can be piped directly to it:
> >
> > dmesg | analyze-initcall-debug.py
> >
> > If no option is specified, it outputs a brief summary, like the following one
> > (obtained on my Beagleplay):
> >
> > 1758 drivers has been initialized, of which 1758 before userspace
> > 119 probes happened outside of the init of their driver
> > 0 deferred probes pending
> > ---
> > Top 10 init/probes durations:
> > * 30200000.dss -> 523002us
> > * deferred_probe_initcall -> 487483us
> > * fd00000.gpu -> 162859us
> > * 8000f00.mdio -> 142521us
> > * 44043000.system-controller -> 71390us
> > * 2-004c -> 71178us
> > * 40900000.crypto -> 59350us
> > * 8000000.ethernet -> 58419us
> > * 44043000.system-controller:clock-controller -> 56599us
> > * jent_mod_init -> 52140us
> >
> > A more complete output, reporting all durations as well as statuses, impact of
> > probe deferral and so on, can be produced either in HTML or Markdown format,
> > using respectively the --html or --markdown parameters.
> >
> > Note: it hasn't (yet?) been used in a "production" environment, as I never
> > found the motivation to write a script and always analyzed manually the
> > initcall_debug output.
> >
> > If you have time to take a look, please tell me what you think and what
> > can be added.
> >
> > Thank you!
> >
> > Regards,
> > Francesco
> >
> > [1] https://lore.kernel.org/linux-
> > embedded/MW5PR13MB5632F54DCBDA0C74370E531FFD5C2@MW5PR13MB5632.namprd13.prod.outlook.com/
> >
> > --- analyze-initcall-debug.py script follows ---
> >
> > #!/usr/bin/env python3
> > # -*- coding: utf-8 -*-
> >
> > """
> > This script can be used to analyze a Linux kernel dmesg output when the
> > initcall_debug command line output is used. It extract various information,
> > such as init durations, impact of probe deferral and so on.
> > """
> >
> > import argparse
> > import re
> > import sys
> >
> > ERRCODE_PROBE_DEFER = 517
> >
> > parser = argparse.ArgumentParser()
> >
> > parser.add_argument('--dmesg', nargs='?', type=argparse.FileType('r'),
> > default=sys.stdin)
> > parser.add_argument('--html', action='store_true')
> > parser.add_argument('--markdown', action='store_true')
> > args = parser.parse_args()
> >
> > class Run:
> > def __init__(self, start_time:int, end_time:int = -1, duration:int = 0, retval:int = 0):
> > self._start_time = start_time
> > self._end_time = end_time
> > self._duration = duration
> > self._retval = retval
> > self._ended = (end_time >= 0)
> >
> > @property
> > def start_time(self) -> int:
> > return self._start_time
> >
> > @property
> > def end_time(self) -> int:
> > return self._end_time
> >
> > @end_time.setter
> > def end_time(self, time:int):
> > self._end_time = time
> > self._ended = True
> >
> > @property
> > def duration(self) -> int:
> > return self._duration
> >
> > @duration.setter
> > def duration(self, time:int):
> > self._duration = time
> >
> > @property
> > def retval(self) -> int:
> > return self._retval
> >
> > @retval.setter
> > def retval(self, val:int):
> > self._retval = val
> >
> > @property
> > def running(self) -> bool:
> > return (not self._ended or abs(self.retval) == ERRCODE_PROBE_DEFER)
> >
> > @property
> > def failed(self) -> bool:
> > return ((self.retval != 0) and not self.running)
> >
> >
> > class Entity:
> > def __init__(self, name:str, start_time:int = 0, end_time:int = 0, duration:int = 0, retval:int = 0):
> > self._name = name
> > self._runs = [ Run(start_time, end_time, duration, retval) ]
> >
> > @property
> > def name(self) -> str:
> > return self._name
> >
> > @property
> > def first_start_time(self) -> int:
> > return self._runs[0].start_time
> >
> > @property
> > def last_start_time(self) -> int:
> > return self._runs[-1].start_time
> >
> > @property
> > def first_end_time(self) -> int:
> > return self._runs[0].end_time
> >
> > @property
> > def last_end_time(self) -> int:
> > return self._runs[-1].end_time
> >
> > @property
> > def duration(self) -> int:
> > return sum([ r.duration for r in self._runs ])
> >
> > @property
> > def wasted_time(self) -> int:
> > return sum([ r.duration for r in filter(lambda x: x.failed or abs(x.retval) == ERRCODE_PROBE_DEFER, self._runs) ])
> >
> > @property
> > def retval(self) -> int:
> > return self._runs[-1].retval
> >
> > @property
> > def failed(self) -> bool:
> > return self._runs[-1].failed
> >
> > @property
> > def running(self) -> bool:
> > return self._runs[-1].running
> >
> > @property
> > def deferred_probe_pending(self) -> bool:
> > return (abs(self._runs[-1].retval) == ERRCODE_PROBE_DEFER)
> >
> > @property
> > def num_deferred_probes(self) -> int:
> > return len(list(filter(lambda r: abs(r.retval) == ERRCODE_PROBE_DEFER, self._runs)))
> >
> > def addStart(self, start_time: int):
> > self._runs.append( Run(start_time) )
> >
> > def addEnd(self, end_time:int = 0, duration:int = 0, retval:int = 0):
> > self._runs[-1].end_time = end_time
> > self._runs[-1].duration = duration
> > self._runs[-1].retval = retval
> >
> > def addRun(self, start_time: int, end_time:int = 0, duration:int = 0, retval:int = 0):
> > self._runs.append( Run(start_time, end_time, duration, retval) )
> >
> >
> > class Driver (Entity):
> > def __init__(self, name: str, start_time: int):
> > super().__init__(name, start_time)
> >
> > def addInit(self, init_time: int):
> > self.addStart(init_time)
> >
> > def addReturn(self, return_time: int, duration: int, retval: int):
> > self.addEnd(return_time, duration, retval)
> >
> >
> > class Probe (Entity):
> > def __init__(self, name: str, return_time: int, duration: int, retval: int):
> > super().__init__(name, return_time, return_time, duration, retval)
> >
> >
> > class Init (Entity):
> > def __init__(self, name: str, start_time: int):
> > super().__init__(name, start_time)
> >
> >
> > # Regex for 'calling' messages
> > # "[ 0.466115] calling pci_sysfs_init+0x0/0xa8 @ 1"
> > calling_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] calling ([0-9a-zA-Z_]+)\+(0x[0-9a-fA-F]+\/0x[0-9a-fA-F]+) @ ([0-9]+)')
> >
> > # Regex for 'initcall ... returned' messages
> > # "[ 0.466115] initcall pci_sysfs_init+0x0/0xa8 returned 0 after 5 usecs"
> > returned_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] initcall ([0-9a-zA-Z_]+)\+(0x[0-9a-fA-F]+\/0x[0-9a-fA-F]+) returned ([\-0-9]+) after ([0-
> > 9]+) usecs')
> >
> > # Regex for 'probe ... returned' messages
> > # "[ 0.466115] probe of cpufreq-dt returned 517 after 140 usec"
> > probe_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] probe of ([0-9a-zA-Z_\-\.\:@]+) returned ([\-0-9]+) after ([0-9]+) usecs')
> >
> > # Regex for
> > # "[ 1.060329] Run /sbin/init as init process"
> > init_prog = re.compile(r'\[([0-9\s]+\.[0-9]+)\] Run ([/0-9a-zA-Z_]+) as init process')
> >
>
> I'm a little worried about the fragility of these regex lines. If a dmesg line doesn't
> match, then it is silently ignored. It might be worth checking for a simpler match first,
> then trying for the full regex match. See below.
>
You are right - in fact this version of the tool is not matching probes for drivers
built as modules. I'll post an updated version once I solved all the other concerns.
> > drivers = list()
> > probes = list()
> > init = None
> >
> > # Extract data from dmesg
> > for line in args.dmesg:
> It might be nice to keep track of the line number here, for more detail
> when reporting parsing errors.
>
Agreed.
> > match = calling_prog.match(line)
>
> if "] calling" in line:
> match = calling_prog.match(line)
>
Yes, that would be better.
> > if match is not None:
>
> if match:
> is better here, IMHO.
>
Noted (for the other occurrences below, too).
> > time = float(match.group(1)) * float(10^6)
> > name = str(match.group(2))
> > try:
> > time = float(match.group(1)) * float(10^6)
> > name = str(match.group(2))
> > except Exception as e:
> > print(f'Failed parsing line "{line.rstrip()}" as call')
> > raise e
> > else:
> > for d in filter(lambda x: x.name == name, drivers):
> This is a bit strange.
> Why not use a dictionary for drivers here, with name as the key, instead
> of a list where you have to do a search?
>
Force of habit, probably - I code 99% of the time in C. A dictionary would be more efficient.
> > d.addInit(time)
> > break
> > else:
> > drivers.append(Driver(name, time))
> If the driver names are unique, then this can be:
> drivers[name] = Driver(name, time)
> Otherwise:
> drivers[name] = drivers.get(name, []).append(Drivers(name, time))
>
> which is equivalent to:
> if name in drivers:
> drivers[name].append(Driver(name, time))
> else:
> drivers[name] = [Drivers(name, time)]
>
Noted. I need to think about the .get().append() syntax, is not so intuitive to me.
> > finally:
> > continue
> >
> > match = returned_prog.match(line)
> > if match is not None:
> if match:
>
> > try:
> > time = float(match.group(1)) * float(10^6)
> > name = str(match.group(2))
> > retval = int(match.group(4))
> > duration = int(match.group(5))
> > except:
> > print(f'Failed parsing line "{line.rstrip()}" as call return')
> > else:
> > for d in filter(lambda x: x.name == name, drivers):
> Same thing here - should use a dictionary with name as key.
>
Yes - see above.
> > d.addReturn(time, duration, retval)
> > break
> > else:
> > print(f'Detected return for driver {name}, for which an init was never recorded')
> > finally:
> > continue
> >
> > match = probe_prog.match(line)
> > if match is not None:
> if match:
> > try:
> > time = float(match.group(1)) * float(10^6)
> > name = str(match.group(2))
> > retval = int(match.group(3))
> > duration = int(match.group(4))
> > except:
> > print(f'Failed parsing line "{line.rstrip()}" as probe return')
> > else:
> > for d in filter(lambda x: x.name == name, probes):
> Should use a dictionary here.
> > d.addRun(time, time, duration, retval)
> > break
> > else:
> > probes.append(Probe(name, time, duration, retval))
> > finally:
> > continue
> >
> > if init is None:
> if not init:
> > match = init_prog.match(line)
> > if match is not None:
> if match:
> > try:
> > time = float(match.group(1)) * float(10^6)
> > name = str(match.group(2))
> > except:
> > print(f'Failed parsing line "{line.rstrip()}" as probe return')
> > else:
> > init = Init(name, time)
> > finally:
> > continue
> >
> > if args.markdown:
> > print('| Name | Type [^1] | Status [^2] | Duration (us) | Before userspace | Num deferred probes | Time spent in failed inits (us) |')
> > print('| -----| --------- | ----------- | ------------- | ---------------- | ------------------- | ------------------------------- |')
> > for d in sorted(filter(lambda k: k.duration > 0, drivers + probes), key=lambda k: k.duration, reverse=True):
> > etype = 'I' if d in drivers else 'P'
> > run_status = 'D' if d.deferred_probe_pending else 'R' if d.running else f'F({abs(d.retval)})' if d.failed else 'K'
> > before_init = 'Y' if d.last_start_time < init.last_start_time else 'N'
> > print(f'| {d.name} | {etype} | {run_status} | {d.duration} | {before_init} | {d.num_deferred_probes} | {d.wasted_time} |')
> > print('[^1]: I=Init function, P=device Probe')
> > print('[^2]: D=Deferred probe pending, R=still Running, F(N)=Failed (with errcode N), K=init oK')
> > elif args.html:
> > print(
> > '''
> > <!DOCTYPE HTML>
> > <html>
> > <head>
> > <meta charset="utf-8" />
> > <title>Initcall analysis</title>
> > <meta name="viewport" content="width=device-width, initial-scale=1" />
> > <style>
> > table, th, td {
> > border: 1px solid;
> > }
> > </style>
> > </head>
> > <body>
> >
> I'd like a version of this where it just emits the HTML for the body, and not the full
> page. I could use this in my birdcloud boot-time wiki.
>
> Maybe add an option to select full HTML page vs HTML snippet?
>
I'll add an option to do just that.
> > <table>
> > <tr>
> > <th>Name</th>
> > <th>Type <a href="#note1">[1]</a></th>
> > <th>Status <a href="#note2">[2]</a></th>
> > <th>Duration (us)</th>
> > <th>Before userspace</th>
> > <th>Num deferred probes</th>
> > <th>Time spent in failed inits (us)</th>
> > </tr>''')
> >
> > for d in sorted(filter(lambda k: k.duration > 0, drivers + probes), key=lambda k: k.duration, reverse=True):
> > etype = 'I' if d in drivers else 'P'
> > run_status = 'D' if d.deferred_probe_pending else 'R' if d.running else f'F({abs(d.retval)})' if d.failed else 'K'
> > before_init = 'Y' if d.last_start_time < init.last_start_time else 'N'
> > print(
> > f'''
> > <tr>
> > <td>{d.name}</td>
> > <td>{etype}</td>
> > <td>{run_status}</td>
> > <td>{d.duration}</td>
> > <td>{before_init}</td>
> > <td>{d.num_deferred_probes}</td>
> > <td>{d.wasted_time}</td>
> > </tr>''')
> >
> > print(
> > '''
> > </table>
> > <p id="note1">[1] I=Init function, P=device Probe</p>
> > <p id="note2">[2] D=Deferred probe pending, R=still Running, F(N)=Failed (with errcode N), K=init oK</p>
> > </body>
> > </html>
> > ''')
> >
> > else:
> > print(f'{len(drivers)} drivers has been initialized, of which {len(list(filter(lambda d: d.last_start_time < init.last_start_time, drivers)))}
> > before userspace')
> > print(f'{len(probes)} probes happened outside of the init of their driver')
> >
> > print(f'{len(list(filter(lambda d: d.deferred_probe_pending, drivers + probes)))} deferred probes pending')
> >
> > print('---')
> >
> > print('Top 10 init/probes durations:')
> > for d in sorted(filter(lambda k: k.duration > 0, drivers + probes), key=lambda k: k.duration, reverse=True)[0:10]:
> > print(f' * {d.name} -> {d.duration}us')
> >
> >
> >
> >
>
> Just my 2 cents...
> -- Tim
>
Thank you!
Regards,
Francesco
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-12-05 12:57 ` Francesco Valla
@ 2024-12-05 14:58 ` Geert Uytterhoeven
2024-12-05 21:36 ` Francesco Valla
2024-12-09 3:10 ` [RFC PATCH] boot-time: instrument probes more Bird, Tim
1 sibling, 1 reply; 26+ messages in thread
From: Geert Uytterhoeven @ 2024-12-05 14:58 UTC (permalink / raw)
To: Francesco Valla; +Cc: Linux Embedded, Bird, Tim
Hi Francesco,
On Thu, Dec 5, 2024 at 3:47 PM Francesco Valla <francesco@valla.it> wrote:
> On Tuesday, 3 December 2024 at 21:33:06 Bird, Tim <Tim.Bird@sony.com> wrote:
> > > From: Francesco Valla <francesco@valla.it>
> > > Top 10 init/probes durations:
> > > * 30200000.dss -> 523002us
> >
> > This call, and a lot of the others are missing function names. Did you compile the kernel with
> > CONFIG_KALLSYMS=y?
> >
> > If that's the case, is there a way to use the System.map file for the kernel (used on
> > the machine where the dmesg was obtained from) to map these addresses
> > to their respective function names?
>
> These are not in fact addresses, but rather device names. In my understanding, they are printed
> when a probe happens outside of the initialization function for their driver. I still don't have an idea
> on how to match probes with their original initcall, in order to present the user the complete picture.
30200000.dss corresponds to dss@30200000 in the DTS.
$ git grep -W dss@30200000 | grep compatible
arch/arm64/boot/dts/ti/k3-am62-main.dtsi- compatible = "ti,am625-dss";
arch/arm64/boot/dts/ti/k3-am62a-main.dtsi- compatible = "ti,am62a7-dss";
$ git grep -Ww ti,am625-dss -- drivers/ | grep of_device_id
drivers/gpu/drm/tidss/tidss_drv.c=static const struct of_device_id
tidss_of_table[] = {
$ git grep -Ww tidss_of_table | grep _driver
drivers/gpu/drm/tidss/tidss_drv.c=static struct platform_driver
tidss_platform_driver = {
$ git grep -Ww tidss_platform_driver | grep module
drivers/gpu/drm/tidss/tidss_drv.c:drm_module_platform_driver(tidss_platform_driver);
Gr{oetje,eeting}s,
Geert
--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org
In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
-- Linus Torvalds
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-12-05 14:58 ` Geert Uytterhoeven
@ 2024-12-05 21:36 ` Francesco Valla
0 siblings, 0 replies; 26+ messages in thread
From: Francesco Valla @ 2024-12-05 21:36 UTC (permalink / raw)
To: Geert Uytterhoeven; +Cc: Linux Embedded, Bird, Tim
Hi Geert,
On Thursday, 5 December 2024 at 15:58:09 Geert Uytterhoeven <geert@linux-m68k.org> wrote:
> Hi Francesco,
>
> On Thu, Dec 5, 2024 at 3:47 PM Francesco Valla <francesco@valla.it> wrote:
> > On Tuesday, 3 December 2024 at 21:33:06 Bird, Tim <Tim.Bird@sony.com> wrote:
> > > > From: Francesco Valla <francesco@valla.it>
> > > > Top 10 init/probes durations:
> > > > * 30200000.dss -> 523002us
> > >
> > > This call, and a lot of the others are missing function names. Did you compile the kernel with
> > > CONFIG_KALLSYMS=y?
> > >
> > > If that's the case, is there a way to use the System.map file for the kernel (used on
> > > the machine where the dmesg was obtained from) to map these addresses
> > > to their respective function names?
> >
> > These are not in fact addresses, but rather device names. In my understanding, they are printed
> > when a probe happens outside of the initialization function for their driver. I still don't have an idea
> > on how to match probes with their original initcall, in order to present the user the complete picture.
>
> 30200000.dss corresponds to dss@30200000 in the DTS.
>
This is a simple example, but what about e.g. an I2C device (say 2-004c)? Some heuristic
would be needed to search for the correct I2C bus and then the 0x4c device; once found,
the compatible would then need to be searched through the entire kernel sources / git repo
to match it to the correct driver.
At that point, the tool would probably be too complex to be maintainable, while the added
value very little IMO (in my experience, boot time optimization is done by experienced
developers, which can match a probe with its driver quite easily, even if manually).
Thank you!
Regards,
Francesco
^ permalink raw reply [flat|nested] 26+ messages in thread
* [RFC PATCH] boot-time: instrument probes more
2024-12-05 12:57 ` Francesco Valla
2024-12-05 14:58 ` Geert Uytterhoeven
@ 2024-12-09 3:10 ` Bird, Tim
2024-12-21 14:47 ` Francesco Valla
1 sibling, 1 reply; 26+ messages in thread
From: Bird, Tim @ 2024-12-09 3:10 UTC (permalink / raw)
To: Francesco Valla, Linux Embedded
> -----Original Message-----
> From: Francesco Valla <francesco@valla.it>
...
> On Tuesday, 3 December 2024 at 21:33:06 Bird, Tim <Tim.Bird@sony.com> wrote:
...
> > > -----Original Message-----
> > > From: Francesco Valla <francesco@valla.it>
...
> > > * deferred_probe_initcall -> 487483us
> >
> > I feel like this function is interfering with the ability to correctly assign
> > boot time delays to the correct initcall.
> >
> > I would really like to see someone tackle this issue, by studying the deferred_probe_initcall
> > function, to see if there's a way to instrument it so that the cost of each
> > probe can be reported and then associated with corresponding initcall, when initcall_debug
> > is used.
> >
> > Does anyone want to look into this issue?
>
> I can take a look, but probably toward the end of the year. Another similar area I'd like to investigate
> is related to initcall time vs actual probe time: for drivers instantiated multiple time, I'd like to know
> how much time each probe took rather than the overall time.
OK - here's an experimental patch to instrument deferred probing more. It builds on
the already existing instrumentation for initcall_debug, but prints a bit more detail
about the probe function that is in effect during certain delays during boot.
Here is some output, from a kernel with this patch, filtered by grepping for "probe":
(this was on a beagleplay running a kernel with initcall_debug turned on)
$ ttc bp1 run "dmesg | grep probe"
[ 0.003825] calling init_kprobes+0x0/0x190 @ 1
[ 0.004085] initcall init_kprobes+0x0/0x190 returned 0 after 4000 usecs
[ 0.044089] calling trace_events_eprobe_init_early+0x0/0x60 @ 1
[ 0.044101] initcall trace_events_eprobe_init_early+0x0/0x60 returned 0 after 0 usecs
[ 0.044112] calling init_kprobe_trace_early+0x0/0x48 @ 1
[ 0.044125] initcall init_kprobe_trace_early+0x0/0x48 returned 0 after 0 usecs
[ 0.046498] platform probe dummy_regulator_probe is being called
[ 0.046674] probe platform_probe in driver reg-dummy for device reg-dummy returned 0 after 0 usecs
[ 0.049728] calling release_early_probes+0x0/0x70 @ 1
[ 0.049739] initcall release_early_probes+0x0/0x70 returned 0 after 0 usecs
[ 0.057708] probe platform_probe in driver davinci_gpio for device 4201000.gpio returned -517 after 0 usecs
[ 0.058357] platform probe sram_probe is being called
[ 0.058463] probe platform_probe in driver sram for device 70000000.sram returned 0 after 0 usecs
[ 0.061883] probe platform_probe in driver davinci_gpio for device 600000.gpio returned -517 after 0 usecs
[ 0.062054] probe platform_probe in driver davinci_gpio for device 601000.gpio returned -517 after 0 usecs
[ 0.070308] platform probe k3_chipinfo_probe is being called
[ 0.070580] probe platform_probe in driver k3-chipinfo for device 43000014.chipid returned 0 after 0 usecs
[ 0.071233] platform probe reg_fixed_voltage_probe is being called
[ 0.071401] probe platform_probe in driver reg-fixed-voltage for device regulator-2 returned -517 after 0 usecs
[ 0.071437] probe platform_probe in driver reg-fixed-voltage for device regulator-3 returned -517 after 0 usecs
[ 0.071461] probe platform_probe in driver reg-fixed-voltage for device regulator-4 returned -517 after 0 usecs
[ 0.071487] probe platform_probe in driver gpio-regulator for device regulator-5 returned -517 after 0 usecs
[ 0.071663] probe platform_probe in driver reg-fixed-voltage for device regulator-1 returned 0 after 0 usecs
[ 0.073156] probe platform_probe in driver omap_i2c for device 4900000.i2c returned -517 after 0 usecs
[ 0.073228] probe platform_probe in driver omap_i2c for device 20000000.i2c returned -517 after 0 usecs
[ 0.073250] probe platform_probe in driver omap_i2c for device 20010000.i2c returned -517 after 0 usecs
[ 0.073272] probe platform_probe in driver omap_i2c for device 20020000.i2c returned -517 after 0 usecs
[ 0.073293] probe platform_probe in driver omap_i2c for device 20030000.i2c returned -517 after 0 usecs
[ 0.074080] platform probe psci_cpuidle_domain_probe is being called
[ 0.074129] probe platform_probe in driver psci-cpuidle-domain for device firmware:psci returned 0 after 0 usecs
[ 0.077465] calling init_kprobe_trace+0x0/0x220 @ 1
[ 0.842940] initcall init_kprobe_trace+0x0/0x220 returned 0 after 765459 usecs
[ 0.843041] calling init_uprobe_trace+0x0/0x98 @ 1
[ 0.843068] initcall init_uprobe_trace+0x0/0x98 returned 0 after 17 usecs
[ 0.855784] calling arch_init_uprobes+0x0/0x48 @ 1
[ 0.855796] initcall arch_init_uprobes+0x0/0x48 returned 0 after 1 usecs
[ 0.893082] platform probe ti_sci_intr_irq_domain_probe is being called
[ 0.893128] probe platform_probe in driver ti-sci-intr for device 4210000.interrupt-controller returned 517 after 111 usecs
[ 0.893318] platform probe ti_sci_intr_irq_domain_probe is being called
[ 0.893339] probe platform_probe in driver ti-sci-intr for device bus@f0000:interrupt-controller@a00000 returned 517 after 54 usecs
[ 0.893557] platform probe ti_sci_inta_irq_domain_probe is being called
[ 0.893575] probe platform_probe in driver ti-sci-inta for device 48000000.interrupt-controller returned 517 after 44 usecs
[ 0.893712] platform probe simple_pm_bus_probe is being called
[ 0.894140] probe platform_probe in driver simple-pm-bus for device bus@f0000 returned 0 after 449 usecs
[ 0.894178] platform probe simple_pm_bus_probe is being called
[ 0.894234] probe platform_probe in driver simple-pm-bus for device bus@f0000:bus@4000000 returned 0 after 78 usecs
[ 0.894279] platform probe simple_pm_bus_probe is being called
[ 0.894317] probe platform_probe in driver simple-pm-bus for device bus@f0000:bus@b00000 returned 0 after 60 usecs
[ 0.894351] platform probe simple_pm_bus_probe is being called
[ 0.894363] probe platform_probe in driver simple-pm-bus for device 43000000.syscon returned 19 after 32 usecs
[ 0.894403] platform probe simple_pm_bus_probe is being called
[ 0.894414] probe platform_probe in driver simple-pm-bus for device 100000.syscon returned 19 after 30 usecs
[ 0.894453] platform probe simple_pm_bus_probe is being called
[ 0.894487] probe platform_probe in driver simple-pm-bus for device bus@f0000:bus@48000000 returned 0 after 54 usecs
[ 0.894574] platform probe simple_pm_bus_probe is being called
[ 0.894601] probe platform_probe in driver simple-pm-bus for device fc00000.bus returned 0 after 47 usecs
[ 0.895465] platform probe phy_gmii_sel_probe is being called
[ 0.895835] probe platform_probe in driver phy-gmii-sel for device 104044.phy returned 0 after 395 usecs
[ 0.896246] platform probe pcs_probe is being called
[ 0.896588] probe platform_probe in driver pinctrl-single for device 4084000.pinctrl returned 0 after 369 usecs
[ 0.896686] platform probe pcs_probe is being called
[ 0.898159] probe platform_probe in driver pinctrl-single for device f4000.pinctrl returned 0 after 1501 usecs
[ 0.900582] platform probe ti_syscon_gate_clk_probe is being called
[ 0.900789] probe platform_probe in driver ti-syscon-gate-clk for device 104130.clock-controller returned 0 after 251 usecs
[ 0.900816] probe platform_probe in driver ti-syscon-gate-clk for device 1082e0.clock-controller returned -517 after 10 usecs
[ 0.900837] probe platform_probe in driver ti-syscon-gate-clk for device 1082e4.clock-controller returned -517 after 7 usecs
[ 0.901084] platform probe udma_probe is being called
[ 0.901191] probe platform_probe in driver ti-udma for device 485c0100.dma-controller returned 517 after 140 usecs
[ 0.901287] platform probe udma_probe is being called
[ 0.901346] probe platform_probe in driver ti-udma for device 485c0000.dma-controller returned 517 after 89 usecs
[ 0.906403] probe serial_ctrl_probe in driver ctrl for device serial8250:0 returned 0 after 37 usecs
[ 0.906481] probe serial_port_probe in driver port for device serial8250:0.0 returned 0 after 18 usecs
[ 0.906812] probe serial_port_probe in driver port for device serial8250:0.1 returned 0 after 21 usecs
[ 0.907078] probe serial_port_probe in driver port for device serial8250:0.2 returned 0 after 17 usecs
[ 0.907328] probe serial_port_probe in driver port for device serial8250:0.3 returned 0 after 17 usecs
[ 0.907580] probe serial_port_probe in driver port for device serial8250:0.4 returned 0 after 17 usecs
[ 0.907848] probe serial_port_probe in driver port for device serial8250:0.5 returned 0 after 17 usecs
[ 0.908102] probe serial_port_probe in driver port for device serial8250:0.6 returned 0 after 18 usecs
[ 0.908353] probe serial_port_probe in driver port for device serial8250:0.7 returned 0 after 17 usecs
[ 0.908604] probe serial_port_probe in driver port for device serial8250:0.8 returned 0 after 16 usecs
[ 0.908852] probe serial_port_probe in driver port for device serial8250:0.9 returned 0 after 16 usecs
[ 0.909110] probe serial_port_probe in driver port for device serial8250:0.10 returned 0 after 17 usecs
[ 0.909420] probe serial_port_probe in driver port for device serial8250:0.11 returned 0 after 19 usecs
[ 0.909771] platform probe serial8250_probe is being called
[ 0.909791] probe platform_probe in driver serial8250 for device serial8250 returned 0 after 41 usecs
[ 0.910194] probe platform_probe in driver omap8250 for device 2800000.serial returned 517 after 121 usecs
[ 0.910228] probe platform_probe in driver omap8250 for device 2850000.serial returned -517 after 16 usecs
[ 0.910251] probe platform_probe in driver omap8250 for device 2860000.serial returned -517 after 7 usecs
[ 0.920029] calling cfi_probe_init+0x0/0x40 @ 1
[ 0.920039] initcall cfi_probe_init+0x0/0x40 returned 0 after 0 usecs
[ 0.923593] probe platform_probe in driver mdio-gpio for device mdio returned -517 after 9 usecs
[ 0.924519] probe platform_probe in driver am65-cpsw-nuss for device 8000000.ethernet returned -517 after 21 usecs
[ 0.925689] probe platform_probe in driver dwc3-am62 for device f900000.dwc3-usb returned -517 after 16 usecs
[ 0.925713] probe platform_probe in driver dwc3-am62 for device f910000.dwc3-usb returned -517 after 7 usecs
[ 0.928710] platform probe ti_cpufreq_probe is being called
[ 0.929101] platform probe dt_cpufreq_probe is being called
[ 0.929161] probe platform_probe in driver cpufreq-dt for device cpufreq-dt returned 517 after 78 usecs
[ 0.929190] probe platform_probe in driver ti-cpufreq for device ti-cpufreq returned 0 after 518 usecs
[ 0.929796] platform probe psci_cpuidle_probe is being called
[ 0.929822] probe platform_probe in driver psci-cpuidle for device psci-cpuidle returned 19 after 46 usecs
[ 0.930416] probe platform_probe in driver sdhci-am654 for device fa10000.mmc returned -517 after 21 usecs
[ 0.930429] probe platform_probe in driver sdhci-am654 for device fa00000.mmc returned -517 after 15 usecs
[ 0.930449] probe platform_probe in driver sdhci-am654 for device fa20000.mmc returned -517 after 19 usecs
[ 0.930922] platform probe gpio_led_probe is being called
[ 0.930973] probe platform_probe in driver leds-gpio for device leds returned 517 after 97 usecs
[ 0.931496] probe platform_probe in driver ti-sci for device 44043000.system-controller returned -517 after 4 usecs
[ 0.932190] probe platform_probe in driver omap_timer for device 2400000.timer returned -517 after 13 usecs
[ 0.932217] probe platform_probe in driver omap_timer for device 2410000.timer returned -517 after 12 usecs
[ 0.932238] probe platform_probe in driver omap_timer for device 2420000.timer returned -517 after 7 usecs
[ 0.932258] probe platform_probe in driver omap_timer for device 2430000.timer returned -517 after 7 usecs
[ 0.932277] probe platform_probe in driver omap_timer for device 2440000.timer returned -517 after 7 usecs
[ 0.932297] probe platform_probe in driver omap_timer for device 2450000.timer returned -517 after 7 usecs
[ 0.932317] probe platform_probe in driver omap_timer for device 2460000.timer returned -517 after 7 usecs
[ 0.932337] probe platform_probe in driver omap_timer for device 2470000.timer returned -517 after 7 usecs
[ 0.933540] platform probe omap_mbox_probe is being called
[ 0.933594] probe platform_probe in driver omap-mailbox for device 29000000.mailbox returned 19 after 104 usecs
[ 0.933746] platform probe ti_msgmgr_probe is being called
[ 0.934097] probe platform_probe in driver ti-msgmgr for device 4d000000.mailbox returned 0 after 380 usecs
[ 0.934692] platform probe armv8_pmu_device_probe is being called
[ 0.935257] probe platform_probe in driver armv8-pmu for device pmu returned 0 after 593 usecs
[ 0.935845] platform probe optee_probe is being called
[ 0.952849] probe platform_probe in driver optee for device firmware:optee returned 0 after 17036 usecs
[ 0.954457] platform probe snd_soc_dummy_probe is being called
[ 0.954498] probe platform_probe in driver snd-soc-dummy for device snd-soc-dummy returned 0 after 73 usecs
[ 0.963947] calling debugfs_kprobe_init+0x0/0xc0 @ 1
[ 0.963974] initcall debugfs_kprobe_init+0x0/0xc0 returned 0 after 17 usecs
[ 0.973856] calling deferred_probe_initcall+0x0/0xc8 @ 1
[ 0.973989] probe platform_probe in driver davinci_gpio for device 4201000.gpio returned -517 after 24 usecs
[ 0.974036] probe platform_probe in driver davinci_gpio for device 600000.gpio returned -517 after 8 usecs
[ 0.974071] probe platform_probe in driver davinci_gpio for device 601000.gpio returned -517 after 7 usecs
[ 0.974627] platform probe reg_fixed_voltage_probe is being called
[ 0.974730] probe platform_probe in driver reg-fixed-voltage for device regulator-3 returned -517 after 6 usecs
[ 0.974873] probe platform_probe in driver reg-fixed-voltage for device regulator-4 returned -517 after 4 usecs
[ 0.975017] probe platform_probe in driver omap_i2c for device 4900000.i2c returned -517 after 23 usecs
[ 0.975031] probe platform_probe in driver gpio-regulator for device regulator-5 returned -517 after 34 usecs
[ 0.975059] probe platform_probe in driver omap_i2c for device 20000000.i2c returned -517 after 7 usecs
[ 0.975075] probe platform_probe in driver reg-fixed-voltage for device regulator-2 returned 0 after 535 usecs
[ 0.975093] probe platform_probe in driver omap_i2c for device 20010000.i2c returned -517 after 7 usecs
[ 0.975124] probe platform_probe in driver omap_i2c for device 20020000.i2c returned -517 after 7 usecs
[ 0.975156] probe platform_probe in driver omap_i2c for device 20030000.i2c returned -517 after 7 usecs
[ 0.975238] platform probe ti_sci_intr_irq_domain_probe is being called
[ 0.975272] probe platform_probe in driver ti-sci-intr for device 4210000.interrupt-controller returned 517 after 88 usecs
[ 0.975471] platform probe ti_sci_intr_irq_domain_probe is being called
[ 0.975488] probe platform_probe in driver ti-sci-intr for device bus@f0000:interrupt-controller@a00000 returned 517 after 44 usecs
[ 0.975649] platform probe ti_sci_inta_irq_domain_probe is being called
[ 0.975667] probe platform_probe in driver ti-sci-inta for device 48000000.interrupt-controller returned 517 after 46 usecs
[ 0.975826] probe platform_probe in driver ti-syscon-gate-clk for device 1082e0.clock-controller returned -517 after 8 usecs
[ 0.975885] probe platform_probe in driver ti-syscon-gate-clk for device 1082e4.clock-controller returned -517 after 8 usecs
[ 0.975967] platform probe udma_probe is being called
[ 0.976095] probe platform_probe in driver ti-udma for device 485c0100.dma-controller returned 517 after 157 usecs
[ 0.976258] platform probe udma_probe is being called
[ 0.976315] probe platform_probe in driver ti-udma for device 485c0000.dma-controller returned 517 after 85 usecs
[ 0.976558] probe platform_probe in driver omap8250 for device 2800000.serial returned 517 after 93 usecs
[ 0.976723] probe platform_probe in driver omap8250 for device 2850000.serial returned -517 after 11 usecs
[ 0.976804] probe platform_probe in driver omap8250 for device 2860000.serial returned -517 after 7 usecs
[ 0.976888] probe platform_probe in driver mdio-gpio for device mdio returned -517 after 3 usecs
[ 0.976986] probe platform_probe in driver am65-cpsw-nuss for device 8000000.ethernet returned -517 after 8 usecs
[ 0.977082] probe platform_probe in driver dwc3-am62 for device f900000.dwc3-usb returned -517 after 8 usecs
[ 0.977178] probe platform_probe in driver dwc3-am62 for device f910000.dwc3-usb returned -517 after 7 usecs
[ 0.977308] platform probe dt_cpufreq_probe is being called
[ 0.977371] probe platform_probe in driver cpufreq-dt for device cpufreq-dt returned 517 after 93 usecs
[ 0.977707] probe platform_probe in driver sdhci-am654 for device fa10000.mmc returned -517 after 13 usecs
[ 0.977869] probe platform_probe in driver sdhci-am654 for device fa00000.mmc returned -517 after 16 usecs
[ 0.978019] probe platform_probe in driver sdhci-am654 for device fa20000.mmc returned -517 after 9 usecs
[ 0.978054] platform probe gpio_led_probe is being called
[ 0.978102] probe platform_probe in driver leds-gpio for device leds returned 517 after 95 usecs
[ 0.978264] platform probe ti_sci_probe is being called
[ 0.981447] platform probe ti_sci_pm_domain_probe is being called
[ 0.982522] probe platform_probe in driver ti_sci_pm_domains for device 44043000.system-controller:power-controller returned 0 after 1140 usecs
[ 0.984639] platform probe ti_sci_clk_probe is being called
[ 1.036888] probe platform_probe in driver ti-sci-clk for device 44043000.system-controller:clock-controller returned 0 after 52299 usecs
[ 1.037414] platform probe ti_sci_reset_probe is being called
[ 1.037459] probe platform_probe in driver ti-sci-reset for device 44043000.system-controller:reset-controller returned 0 after 101 usecs
[ 1.037504] probe platform_probe in driver ti-sci for device 44043000.system-controller returned 0 after 59269 usecs
[ 1.037910] platform probe omap_dm_timer_probe is being called
[ 1.038244] probe platform_probe in driver omap_timer for device 2400000.timer returned 0 after 474 usecs
[ 1.038564] platform probe omap_dm_timer_probe is being called
[ 1.038788] probe platform_probe in driver omap_timer for device 2410000.timer returned 0 after 327 usecs
[ 1.039185] platform probe omap_dm_timer_probe is being called
[ 1.039449] probe platform_probe in driver omap_timer for device 2420000.timer returned 0 after 393 usecs
[ 1.039752] platform probe omap_dm_timer_probe is being called
[ 1.039948] probe platform_probe in driver omap_timer for device 2430000.timer returned 0 after 300 usecs
[ 1.040211] platform probe omap_dm_timer_probe is being called
[ 1.040394] probe platform_probe in driver omap_timer for device 2440000.timer returned 0 after 281 usecs
[ 1.040647] platform probe omap_dm_timer_probe is being called
[ 1.040840] probe platform_probe in driver omap_timer for device 2450000.timer returned 0 after 287 usecs
[ 1.041096] platform probe omap_dm_timer_probe is being called
[ 1.041348] probe platform_probe in driver omap_timer for device 2460000.timer returned 0 after 351 usecs
[ 1.041623] platform probe omap_dm_timer_probe is being called
[ 1.041812] probe platform_probe in driver omap_timer for device 2470000.timer returned 0 after 290 usecs
[ 1.041845] probe platform_probe in driver davinci_gpio for device 4201000.gpio returned -517 after 7 usecs
[ 1.041879] probe platform_probe in driver davinci_gpio for device 600000.gpio returned -517 after 3 usecs
[ 1.041908] probe platform_probe in driver davinci_gpio for device 601000.gpio returned -517 after 3 usecs
[ 1.042164] probe platform_probe in driver reg-fixed-voltage for device regulator-3 returned -517 after 5 usecs
[ 1.042293] probe platform_probe in driver reg-fixed-voltage for device regulator-4 returned -517 after 3 usecs
[ 1.042448] platform probe omap_i2c_probe is being called
[ 1.043411] probe platform_probe in driver omap_i2c for device 4900000.i2c returned 0 after 1124 usecs
[ 1.043762] probe platform_probe in driver gpio-regulator for device regulator-5 returned -517 after 16 usecs
[ 1.043940] platform probe omap_i2c_probe is being called
[ 1.070994] platform probe tps65219_regulator_probe is being called
[ 1.070994] platform probe tps65219_gpio_probe is being called
[ 1.071562] probe platform_probe in driver tps65219-gpio for device tps65219-gpio.1.auto returned 0 after 608 usecs
[ 1.072220] probe i2c_device_probe in driver tps65219 for device 0-0030 returned 0 after 26681 usecs
[ 1.072780] probe platform_probe in driver omap_i2c for device 20000000.i2c returned 0 after 29033 usecs
[ 1.073092] platform probe omap_i2c_probe is being called
[ 1.074288] probe platform_probe in driver omap_i2c for device 20010000.i2c returned 0 after 1442 usecs
[ 1.074580] platform probe omap_i2c_probe is being called
[ 1.076436] probe platform_probe in driver omap_i2c for device 20020000.i2c returned 0 after 2067 usecs
[ 1.076737] platform probe omap_i2c_probe is being called
[ 1.077779] probe platform_probe in driver omap_i2c for device 20030000.i2c returned 0 after 1273 usecs
[ 1.077917] platform probe ti_sci_intr_irq_domain_probe is being called
[ 1.078074] probe platform_probe in driver ti-sci-intr for device 4210000.interrupt-controller returned 0 after 214 usecs
[ 1.078171] platform probe ti_sci_intr_irq_domain_probe is being called
[ 1.078272] probe platform_probe in driver ti-sci-intr for device bus@f0000:interrupt-controller@a00000 returned 0 after 132 usecs
[ 1.078332] platform probe ti_sci_inta_irq_domain_probe is being called
[ 1.078346] probe platform_probe in driver tps65219-pmic for device tps65219-regulator.0.auto returned 0 after 7393 usecs
[ 1.078574] probe platform_probe in driver ti-sci-inta for device 48000000.interrupt-controller returned 0 after 273 usecs
[ 1.078749] platform probe ti_syscon_gate_clk_probe is being called
[ 1.079164] probe platform_probe in driver ti-syscon-gate-clk for device 1082e0.clock-controller returned 0 after 473 usecs
[ 1.079287] platform probe ti_syscon_gate_clk_probe is being called
[ 1.079527] probe platform_probe in driver ti-syscon-gate-clk for device 1082e4.clock-controller returned 0 after 279 usecs
[ 1.079628] platform probe udma_probe is being called
[ 1.084883] probe platform_probe in driver ti-udma for device 485c0100.dma-controller returned 0 after 5285 usecs
[ 1.085124] platform probe udma_probe is being called
[ 1.092231] probe platform_probe in driver ti-udma for device 485c0000.dma-controller returned 0 after 7165 usecs
[ 1.092699] platform probe omap8250_probe is being called
[ 1.093664] probe serial_ctrl_probe in driver ctrl for device 2800000.serial:0 returned 0 after 38 usecs
[ 1.093742] probe serial_port_probe in driver port for device 2800000.serial:0.0 returned 0 after 18 usecs
[ 1.158223] probe platform_probe in driver omap8250 for device 2800000.serial returned 0 after 65754 usecs
[ 1.158640] platform probe omap8250_probe is being called
[ 1.159478] probe serial_ctrl_probe in driver ctrl for device 2850000.serial:0 returned 0 after 32 usecs
[ 1.159564] probe serial_port_probe in driver port for device 2850000.serial:0.0 returned 0 after 18 usecs
[ 1.159933] probe platform_probe in driver omap8250 for device 2850000.serial returned 0 after 1485 usecs
[ 1.160268] platform probe omap8250_probe is being called
[ 1.161013] probe serial_ctrl_probe in driver ctrl for device 2860000.serial:0 returned 0 after 30 usecs
[ 1.161091] probe serial_port_probe in driver port for device 2860000.serial:0.0 returned 0 after 18 usecs
[ 1.161705] probe platform_probe in driver omap8250 for device 2860000.serial returned 0 after 1598 usecs
[ 1.162091] probe platform_probe in driver mdio-gpio for device mdio returned -517 after 8 usecs
[ 1.162693] platform probe am65_cpsw_nuss_probe is being called
[ 1.180111] probe platform_probe in driver am65-cpsw-nuss for device 8000000.ethernet returned 0 after 17869 usecs
[ 1.180627] platform probe dwc3_ti_probe is being called
[ 1.195673] platform probe dwc3_probe is being called
[ 1.198203] probe platform_probe in driver dwc3 for device 31000000.usb returned 0 after 2569 usecs
[ 1.198449] probe platform_probe in driver dwc3-am62 for device f900000.dwc3-usb returned 0 after 18007 usecs
[ 1.198933] platform probe dwc3_ti_probe is being called
[ 1.214312] platform probe dwc3_probe is being called
[ 1.214861] platform probe xhci_generic_plat_probe is being called
[ 1.216389] probe usb_probe_interface in driver hub for device 1-0:1.0 returned 0 after 237 usecs
[ 1.216467] probe usb_probe_device in driver usb for device usb1 returned 0 after 436 usecs
[ 1.216536] probe platform_probe in driver xhci-hcd for device xhci-hcd.3.auto returned 0 after 1703 usecs
[ 1.216576] probe platform_probe in driver dwc3 for device 31100000.usb returned 0 after 2380 usecs
[ 1.216939] probe platform_probe in driver dwc3-am62 for device f910000.dwc3-usb returned 0 after 18209 usecs
[ 1.217124] platform probe dt_cpufreq_probe is being called
[ 1.218721] probe platform_probe in driver cpufreq-dt for device cpufreq-dt returned 0 after 1641 usecs
[ 1.219429] probe platform_probe in driver sdhci-am654 for device fa00000.mmc returned -517 after 8 usecs
[ 1.219587] probe platform_probe in driver sdhci-am654 for device fa20000.mmc returned -517 after 4 usecs
[ 1.219603] platform probe gpio_led_probe is being called
[ 1.219603] platform probe sdhci_am654_probe is being called
[ 1.219678] probe platform_probe in driver leds-gpio for device leds returned 517 after 110 usecs
[ 1.219861] platform probe davinci_gpio_probe is being called
[ 1.221502] probe platform_probe in driver davinci_gpio for device 4201000.gpio returned 0 after 1760 usecs
[ 1.221830] platform probe davinci_gpio_probe is being called
[ 1.225318] probe platform_probe in driver davinci_gpio for device 600000.gpio returned 0 after 3732 usecs
[ 1.225607] platform probe davinci_gpio_probe is being called
[ 1.227855] probe platform_probe in driver davinci_gpio for device 601000.gpio returned 0 after 2461 usecs
[ 1.228478] platform probe reg_fixed_voltage_probe is being called
[ 1.228613] platform probe reg_fixed_voltage_probe is being called
[ 1.228800] platform probe mdio_gpio_probe is being called
[ 1.229055] probe platform_probe in driver reg-fixed-voltage for device regulator-4 returned 0 after 531 usecs
[ 1.229055] probe platform_probe in driver reg-fixed-voltage for device regulator-3 returned 0 after 722 usecs
[ 1.229110] platform probe gpio_regulator_probe is being called
[ 1.229760] probe platform_probe in driver gpio-regulator for device regulator-5 returned 0 after 741 usecs
[ 1.231825] probe phy_probe in driver RTL8211F-VD Gigabit Ethernet for device gpio-0:00 returned 0 after 1503 usecs
[ 1.257881] probe platform_probe in driver sdhci-am654 for device fa10000.mmc returned 0 after 38624 usecs
[ 1.310422] probe mmc_bus_probe in driver mmcblk for device mmc0:0001 returned 0 after 4604 usecs
[ 1.366103] probe phy_probe in driver TI DP83TD510E for device gpio-0:01 returned 0 after 68640 usecs
[ 1.366296] probe platform_probe in driver mdio-gpio for device mdio returned 0 after 137582 usecs
[ 1.367130] platform probe gpio_led_probe is being called
[ 1.367262] platform probe sdhci_am654_probe is being called
[ 1.367305] platform probe sdhci_am654_probe is being called
[ 1.367917] probe platform_probe in driver leds-gpio for device leds returned 0 after 862 usecs
[ 1.367997] initcall deferred_probe_initcall+0x0/0xc8 returned 0 after 394128 usecs
[ 1.370955] platform probe gpio_keys_probe is being called
[ 1.371580] probe platform_probe in driver gpio-keys for device gpio-keys returned 0 after 777 usecs
[ 1.406004] probe platform_probe in driver sdhci-am654 for device fa20000.mmc returned 0 after 38948 usecs
[ 1.408093] probe platform_probe in driver sdhci-am654 for device fa00000.mmc returned 0 after 41196 usecs
[ 1.424172] probe mmc_bus_probe in driver mmcblk for device mmc2:0001 returned 19 after 71 usecs
[ 1.624661] probe mmc_bus_probe in driver mmcblk for device mmc1:0001 returned 0 after 3742 usecs
----
Below is the patch that adds the extra instrumentation. My quick question is, does this look useful?
Can it be used to find the more problematic (ie long-duration) probe functions or drivers initializations?
Full boot data from a run with this instrumentation is available at:
https://birdcloud.org/boot-time-files/boot-data-timslab-bp1-241208-191139.txt
Please provide any feedback you have.
-- Tim
----
diff --git a/drivers/base/dd.c b/drivers/base/dd.c
index 0c3725c3eefa..5e19079b0a2b 100644
--- a/drivers/base/dd.c
+++ b/drivers/base/dd.c
@@ -28,6 +28,7 @@
#include <linux/pm_runtime.h>
#include <linux/pinctrl/devinfo.h>
#include <linux/slab.h>
+#include <linux/kallsyms.h>
#include "base.h"
#include "power/power.h"
@@ -732,8 +733,16 @@ static int really_probe(struct device *dev, struct device_driver *drv)
static int really_probe_debug(struct device *dev, struct device_driver *drv)
{
ktime_t calltime, rettime;
+ char fn_name[KSYM_SYMBOL_LEN];
+ unsigned long addr = 0;
int ret;
+ if (dev->bus->probe)
+ addr = (unsigned long)dev->bus->probe;
+ else if (drv->probe)
+ addr = (unsigned long)drv->probe;
+ sprint_symbol_no_offset(fn_name, addr);
+
calltime = ktime_get();
ret = really_probe(dev, drv);
rettime = ktime_get();
@@ -742,8 +751,8 @@ static int really_probe_debug(struct device *dev, struct device_driver *drv)
* CONFIG_DYNAMIC_DEBUG and we want a simple 'initcall_debug' on the
* kernel commandline to print this all the time at the debug level.
*/
- printk(KERN_DEBUG "probe of %s returned %d after %lld usecs\n",
- dev_name(dev), ret, ktime_us_delta(rettime, calltime));
+ printk(KERN_DEBUG "probe %s in driver %s for device %s returned %d after %lld usecs\n",
+ fn_name, drv->name, dev_name(dev), ret, ktime_us_delta(rettime, calltime));
return ret;
}
diff --git a/drivers/base/platform.c b/drivers/base/platform.c
index 76bfcba25003..ae15969c483a 100644
--- a/drivers/base/platform.c
+++ b/drivers/base/platform.c
@@ -32,6 +32,7 @@
#include <linux/types.h>
#include <linux/iommu.h>
#include <linux/dma-map-ops.h>
+#include <linux/kallsyms.h>
#include "base.h"
#include "power/power.h"
@@ -1381,6 +1382,9 @@ static int platform_probe(struct device *_dev)
struct platform_driver *drv = to_platform_driver(_dev->driver);
struct platform_device *dev = to_platform_device(_dev);
int ret;
+ char fn_name[KSYM_SYMBOL_LEN];
+ unsigned long addr = 0;
+
/*
* A driver registered using platform_driver_probe() cannot be bound
@@ -1401,6 +1405,13 @@ static int platform_probe(struct device *_dev)
goto out;
if (drv->probe) {
+ if (initcall_debug) {
+ addr = (unsigned long)drv->probe;
+ sprint_symbol_no_offset(fn_name, addr);
+
+ printk(KERN_DEBUG "platform probe %s is being called\n", fn_name);
+ }
+
ret = drv->probe(dev);
if (ret)
dev_pm_domain_detach(_dev, true);
^ permalink raw reply related [flat|nested] 26+ messages in thread
* Re: [RFC PATCH] boot-time: instrument probes more
2024-12-09 3:10 ` [RFC PATCH] boot-time: instrument probes more Bird, Tim
@ 2024-12-21 14:47 ` Francesco Valla
2024-12-29 17:45 ` Francesco Valla
0 siblings, 1 reply; 26+ messages in thread
From: Francesco Valla @ 2024-12-21 14:47 UTC (permalink / raw)
To: Linux Embedded, Bird, Tim
Hello,
On Monday, 9 December 2024 at 04:10:04 Bird, Tim <Tim.Bird@sony.com> wrote:
> ----
> Below is the patch that adds the extra instrumentation. My quick question is, does this look useful?
> Can it be used to find the more problematic (ie long-duration) probe functions or drivers initializations?
>
Yes, it looks useful to me. While an experienced developer _might_ be able to match
device names and drivers at a quick glance, that's not the case for everyone, in
particular on certain SoCs which are modelled at devicetree level with an exceptionally
high number of "generic" device nodes.
> ----
> diff --git a/drivers/base/dd.c b/drivers/base/dd.c
> index 0c3725c3eefa..5e19079b0a2b 100644
> --- a/drivers/base/dd.c
> +++ b/drivers/base/dd.c
> @@ -28,6 +28,7 @@
> #include <linux/pm_runtime.h>
> #include <linux/pinctrl/devinfo.h>
> #include <linux/slab.h>
> +#include <linux/kallsyms.h>
>
> #include "base.h"
> #include "power/power.h"
> @@ -732,8 +733,16 @@ static int really_probe(struct device *dev, struct device_driver *drv)
> static int really_probe_debug(struct device *dev, struct device_driver *drv)
> {
> ktime_t calltime, rettime;
> + char fn_name[KSYM_SYMBOL_LEN];
> + unsigned long addr = 0;
> int ret;
>
> + if (dev->bus->probe)
> + addr = (unsigned long)dev->bus->probe;
> + else if (drv->probe)
> + addr = (unsigned long)drv->probe;
> + sprint_symbol_no_offset(fn_name, addr);
> +
> calltime = ktime_get();
> ret = really_probe(dev, drv);
> rettime = ktime_get();
> @@ -742,8 +751,8 @@ static int really_probe_debug(struct device *dev, struct device_driver *drv)
> * CONFIG_DYNAMIC_DEBUG and we want a simple 'initcall_debug' on the
> * kernel commandline to print this all the time at the debug level.
> */
> - printk(KERN_DEBUG "probe of %s returned %d after %lld usecs\n",
> - dev_name(dev), ret, ktime_us_delta(rettime, calltime));
> + printk(KERN_DEBUG "probe %s in driver %s for device %s returned %d after %lld usecs\n",
> + fn_name, drv->name, dev_name(dev), ret, ktime_us_delta(rettime, calltime));
> return ret;
> }
>
> diff --git a/drivers/base/platform.c b/drivers/base/platform.c
> index 76bfcba25003..ae15969c483a 100644
> --- a/drivers/base/platform.c
> +++ b/drivers/base/platform.c
> @@ -32,6 +32,7 @@
> #include <linux/types.h>
> #include <linux/iommu.h>
> #include <linux/dma-map-ops.h>
> +#include <linux/kallsyms.h>
>
> #include "base.h"
> #include "power/power.h"
> @@ -1381,6 +1382,9 @@ static int platform_probe(struct device *_dev)
> struct platform_driver *drv = to_platform_driver(_dev->driver);
> struct platform_device *dev = to_platform_device(_dev);
> int ret;
> + char fn_name[KSYM_SYMBOL_LEN];
> + unsigned long addr = 0;
> +
>
> /*
> * A driver registered using platform_driver_probe() cannot be bound
> @@ -1401,6 +1405,13 @@ static int platform_probe(struct device *_dev)
> goto out;
>
> if (drv->probe) {
> + if (initcall_debug) {
> + addr = (unsigned long)drv->probe;
> + sprint_symbol_no_offset(fn_name, addr);
> +
> + printk(KERN_DEBUG "platform probe %s is being called\n", fn_name);
> + }
> +
> ret = drv->probe(dev);
> if (ret)
> dev_pm_domain_detach(_dev, true);
Does this really belong here? Why not add a print inside really_probe_debug(), just
before the call to really_probe()? That approach would catch all probe types (not just
platform_probe) while containing the initcall_debug instrumentation inside dd.c
Regards,
Francesco
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [RFC PATCH] boot-time: instrument probes more
2024-12-21 14:47 ` Francesco Valla
@ 2024-12-29 17:45 ` Francesco Valla
0 siblings, 0 replies; 26+ messages in thread
From: Francesco Valla @ 2024-12-29 17:45 UTC (permalink / raw)
To: Linux Embedded, Bird, Tim
Hello Tim,
On Saturday, 21 December 2024 15:47:54 CET you wrote:
> Hello,
>
> On Monday, 9 December 2024 at 04:10:04 Bird, Tim <Tim.Bird@sony.com> wrote:
> > ----
> > Below is the patch that adds the extra instrumentation. My quick question is, does this look useful?
> > Can it be used to find the more problematic (ie long-duration) probe functions or drivers initializations?
> >
>
> Yes, it looks useful to me. While an experienced developer _might_ be able to match
> device names and drivers at a quick glance, that's not the case for everyone, in
> particular on certain SoCs which are modelled at devicetree level with an exceptionally
> high number of "generic" device nodes.
>
> > ----
> > diff --git a/drivers/base/dd.c b/drivers/base/dd.c
> > index 0c3725c3eefa..5e19079b0a2b 100644
> > --- a/drivers/base/dd.c
> > +++ b/drivers/base/dd.c
> > @@ -28,6 +28,7 @@
> > #include <linux/pm_runtime.h>
> > #include <linux/pinctrl/devinfo.h>
> > #include <linux/slab.h>
> > +#include <linux/kallsyms.h>
> >
> > #include "base.h"
> > #include "power/power.h"
> > @@ -732,8 +733,16 @@ static int really_probe(struct device *dev, struct device_driver *drv)
> > static int really_probe_debug(struct device *dev, struct device_driver *drv)
> > {
> > ktime_t calltime, rettime;
> > + char fn_name[KSYM_SYMBOL_LEN];
> > + unsigned long addr = 0;
> > int ret;
> >
> > + if (dev->bus->probe)
> > + addr = (unsigned long)dev->bus->probe;
> > + else if (drv->probe)
> > + addr = (unsigned long)drv->probe;
> > + sprint_symbol_no_offset(fn_name, addr);
> > +
> > calltime = ktime_get();
> > ret = really_probe(dev, drv);
> > rettime = ktime_get();
> > @@ -742,8 +751,8 @@ static int really_probe_debug(struct device *dev, struct device_driver *drv)
> > * CONFIG_DYNAMIC_DEBUG and we want a simple 'initcall_debug' on the
> > * kernel commandline to print this all the time at the debug level.
> > */
> > - printk(KERN_DEBUG "probe of %s returned %d after %lld usecs\n",
> > - dev_name(dev), ret, ktime_us_delta(rettime, calltime));
> > + printk(KERN_DEBUG "probe %s in driver %s for device %s returned %d after %lld usecs\n",
> > + fn_name, drv->name, dev_name(dev), ret, ktime_us_delta(rettime, calltime));
> > return ret;
> > }
> >
> > diff --git a/drivers/base/platform.c b/drivers/base/platform.c
> > index 76bfcba25003..ae15969c483a 100644
> > --- a/drivers/base/platform.c
> > +++ b/drivers/base/platform.c
> > @@ -32,6 +32,7 @@
> > #include <linux/types.h>
> > #include <linux/iommu.h>
> > #include <linux/dma-map-ops.h>
> > +#include <linux/kallsyms.h>
> >
> > #include "base.h"
> > #include "power/power.h"
> > @@ -1381,6 +1382,9 @@ static int platform_probe(struct device *_dev)
> > struct platform_driver *drv = to_platform_driver(_dev->driver);
> > struct platform_device *dev = to_platform_device(_dev);
> > int ret;
> > + char fn_name[KSYM_SYMBOL_LEN];
> > + unsigned long addr = 0;
> > +
> >
> > /*
> > * A driver registered using platform_driver_probe() cannot be bound
> > @@ -1401,6 +1405,13 @@ static int platform_probe(struct device *_dev)
> > goto out;
> >
> > if (drv->probe) {
> > + if (initcall_debug) {
> > + addr = (unsigned long)drv->probe;
> > + sprint_symbol_no_offset(fn_name, addr);
> > +
> > + printk(KERN_DEBUG "platform probe %s is being called\n", fn_name);
> > + }
> > +
> > ret = drv->probe(dev);
> > if (ret)
> > dev_pm_domain_detach(_dev, true);
>
> Does this really belong here? Why not add a print inside really_probe_debug(), just
> before the call to really_probe()? That approach would catch all probe types (not just
> platform_probe) while containing the initcall_debug instrumentation inside dd.c
>
I had some spare time and I tried to write a patch that maintains the format
of the "return" message (because of backward compatibility) while adding the
details you inserted just before the probe in dd.c.
I then used it on the Beagleplay and I can confirm this helps a lot.
Thank you!
Regards,
Francesco
---
drivers/base/dd.c | 21 +++++++++++++++++----
1 file changed, 17 insertions(+), 4 deletions(-)
diff --git a/drivers/base/dd.c b/drivers/base/dd.c
index f0e4b4aba885..e33ae82064ed 100644
--- a/drivers/base/dd.c
+++ b/drivers/base/dd.c
@@ -28,6 +28,7 @@
#include <linux/pm_runtime.h>
#include <linux/pinctrl/devinfo.h>
#include <linux/slab.h>
+#include <linux/kallsyms.h>
#include "base.h"
#include "power/power.h"
@@ -732,16 +733,28 @@ static int really_probe(struct device *dev, const struct device_driver *drv)
static int really_probe_debug(struct device *dev, const struct device_driver *drv)
{
ktime_t calltime, rettime;
+ char fn_name[KSYM_SYMBOL_LEN];
+ unsigned long addr = 0;
int ret;
- calltime = ktime_get();
- ret = really_probe(dev, drv);
- rettime = ktime_get();
+ if (dev->bus->probe)
+ addr = (unsigned long)dev->bus->probe;
+ else if (drv->probe)
+ addr = (unsigned long)drv->probe;
+ sprint_symbol_no_offset(fn_name, addr);
+
/*
- * Don't change this to pr_debug() because that requires
+ * Don't change this or the one below to pr_debug() because that requires
* CONFIG_DYNAMIC_DEBUG and we want a simple 'initcall_debug' on the
* kernel commandline to print this all the time at the debug level.
*/
+ printk(KERN_DEBUG "calling probe %s in driver %s for device %s\n",
+ fn_name, drv->name, dev_name(dev));
+
+ calltime = ktime_get();
+ ret = really_probe(dev, drv);
+ rettime = ktime_get();
+
printk(KERN_DEBUG "probe of %s returned %d after %lld usecs\n",
dev_name(dev), ret, ktime_us_delta(rettime, calltime));
return ret;
--
2.47.1
^ permalink raw reply related [flat|nested] 26+ messages in thread
* Re: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-12-03 21:24 ` [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Bird, Tim
2024-12-05 7:02 ` Stephan Mueller
@ 2024-12-30 22:22 ` Francesco Valla
2025-01-07 21:27 ` Bird, Tim
1 sibling, 1 reply; 26+ messages in thread
From: Francesco Valla @ 2024-12-30 22:22 UTC (permalink / raw)
To: Linux Embedded, Bird, Tim; +Cc: smueller@chronox.de
On Tuesday, 3 December 2024 at 22:24:28 Bird, Tim <Tim.Bird@sony.com> wrote:
> > -----Original Message-----
> > From: Francesco Valla <francesco@valla.it>
> > Dear fellow boot time optimizers,
> >
> > following the first boot time SIG meeting, which I lurked with much pleasure
> > (but didn't participate to, as I was a bit in awe among such authorities), I'd
> > like to introduce myself with code rather than a presentation or resume.
> >
> > Here is a python script which can analyze a dmesg output with initcall_debug
> > option enabled and extract some useful information. It can for example be used
> > to analyze the output of the grab-boot-data.sh tool that Tim presented on this
> > list [1] just a few days ago.
> >
> > Usage is very simple, as the output of dmesg can be piped directly to it:
> >
> > dmesg | analyze-initcall-debug.py
> >
> > If no option is specified, it outputs a brief summary, like the following one
> > (obtained on my Beagleplay):
> >
> > 1758 drivers has been initialized, of which 1758 before userspace
> > 119 probes happened outside of the init of their driver
> > 0 deferred probes pending
> > ---
> > Top 10 init/probes durations:
> > * 30200000.dss -> 523002us
> > * deferred_probe_initcall -> 487483us
> > * fd00000.gpu -> 162859us
> > * 8000f00.mdio -> 142521us
> > * 44043000.system-controller -> 71390us
> > * 2-004c -> 71178us
> > * 40900000.crypto -> 59350us
> > * 8000000.ethernet -> 58419us
> > * 44043000.system-controller:clock-controller -> 56599us
> > * jent_mod_init -> 52140us
>
> This is odd. On my beagleplay board, jent_mod_init only took 32326us.
> (see https://birdcloud.org/boot-time-files/boot-data-timslab-bp1-241203-134136.txt)
>
> I'm assuming that we have similar hardware, but possibly different configs,
> kernel cmdlines or kernel versions. I'll take a look at this and see if I can
> figure out what the difference is between our systems, that causes the
> difference in the duration for this function.
>
> This initcall (jent_mod_init) is on my list of initcalls to research to see if they
> can be improved or deferred. I haven't seen any degradation in system
> behavior by deferring this initcall on my system, but that could be from
> lack of my system doing some related operation that needs the RNG data, or my
> own ignorance of the effects of this call.
>
> Can someone comment on what items or operations might depend on jent_mod_init
> in early boot? In particular, would we expect any cryptographic problems if
> the initcall was deferred to a few seconds after booting?
>
> It can be configured as a module, which makes me think that maybe loading
> it sometime in very late boot (or even later) is OK.
>
> jent_mod_init is defined in crypto/jitterentropy-kcapi.c, and controlled by
> CONFIG_CRYPTO_JITTERENTROPY (See crypto/Kconfig)
>
> It appears to do some random number generator seeding by measuring
> the jitter of a compressiong operation in the kernel. I assume some of the cryptography
> configs affect the duration of the operations. The initcall duration results on
> my beagleplay seem to be relatively consistent (in the 32ms range consistently),
> and from bobs_lab, on machine sam1, the duration range is also consistent
> (at between 4800 and 5200 usecs).
>
> I'd be interested to see if the range is consistent between runs on other machines
>
> Francesco - Can you submit another boot-data file (or 2 or 3) for francsecoslab-beagleplay, to
> provide some data on this?
>
I actually lost this request and only found it this morning when reviewing past
emails. My apologies.
Anyway: I just uploaded another boot-data file (of a kernel with some
optimizations), but can confirm that the time spent inside jent_mod_init across
multiple runs appears consistent - or should I say fixed? - at 52ms.
Francesco
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
[not found] ` <CAORPcfUfgNnQb6m0baW9qEGnrGYsnbpvwUUmF5Y9Byh9_iMAZw@mail.gmail.com>
@ 2024-12-30 22:35 ` Francesco Valla
2024-12-31 9:55 ` Stephan Müller
2025-01-07 21:42 ` boot markers ideas (was RE: [boot-time] jent_mod_init on beagleplay) Bird, Tim
0 siblings, 2 replies; 26+ messages in thread
From: Francesco Valla @ 2024-12-30 22:35 UTC (permalink / raw)
To: Stephan Mueller, Shankari; +Cc: Linux Embedded, Bird, Tim
Hi Shankari,
On Sunday, 29 December 2024 at 19:52:29 Shankari <beingcap11@gmail.com> wrote:
> Hi
>
> I wanted to provide an update on my recent contributions to the BeaglePlay
> project. I have recently started contributing and have been analyzing the
> boot time of the init process. Below is the output from the system log:
>
> debian@BeaglePlay:~$ dmesg | grep "init process"
> [ 1.480490] Run /init as init process
>
> Moving forward, I plan to explore ways to modify the command line and
> further investigate the data used for SIG analysis. This will help me gain
> a deeper understanding of the boot process and its performance
> characteristics.
I started the same journey around a week ago, and it's proving a valuable
experience.
After some trimming, I reached a (reported) init startup time of around 0.6s:
root@beagleplay-ti:~# dmesg|grep /sbin
[ 0.630046] Run /sbin/init as init process
The result above was obtained on a slightly modified 6.12.4 kernel with a
custom configuration (I am still thinking about the modifications, as they are
a bit unorthodox, but I can share them as well as the defconfig if you are
interested).
>
> Please let me know if you have any suggestions or areas where I could focus
> my efforts.
In general, I'd suggest to use a recent kernel, as I observed a consistent
reduction of boot time between e.g. 6.6.x and 6.12.x.
>
> Best regards,
>
> Shankari
>
Regards,
Francesco
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-12-30 22:35 ` Francesco Valla
@ 2024-12-31 9:55 ` Stephan Müller
2024-12-31 14:42 ` Francesco Valla
2025-01-07 21:42 ` boot markers ideas (was RE: [boot-time] jent_mod_init on beagleplay) Bird, Tim
1 sibling, 1 reply; 26+ messages in thread
From: Stephan Müller @ 2024-12-31 9:55 UTC (permalink / raw)
To: Shankari, Francesco Valla; +Cc: Linux Embedded, Bird, Tim
Am Montag, 30. Dezember 2024, 23:35:03 Mitteleuropäische Normalzeit schrieb
Francesco Valla:
Hi Francesco,
> Hi Shankari,
>
> On Sunday, 29 December 2024 at 19:52:29 Shankari <beingcap11@gmail.com>
wrote:
> > Hi
> >
> > I wanted to provide an update on my recent contributions to the BeaglePlay
> > project. I have recently started contributing and have been analyzing the
> > boot time of the init process. Below is the output from the system log:
> >
> > debian@BeaglePlay:~$ dmesg | grep "init process"
> > [ 1.480490] Run /init as init process
> >
> > Moving forward, I plan to explore ways to modify the command line and
> > further investigate the data used for SIG analysis. This will help me gain
> > a deeper understanding of the boot process and its performance
> > characteristics.
>
> I started the same journey around a week ago, and it's proving a valuable
> experience.
>
> After some trimming, I reached a (reported) init startup time of around
> 0.6s:
>
> root@beagleplay-ti:~# dmesg|grep /sbin
> [ 0.630046] Run /sbin/init as init process
>
> The result above was obtained on a slightly modified 6.12.4 kernel with a
> custom configuration (I am still thinking about the modifications, as they
> are a bit unorthodox, but I can share them as well as the defconfig if you
> are interested).
>
> > Please let me know if you have any suggestions or areas where I could
> > focus
> > my efforts.
>
> In general, I'd suggest to use a recent kernel, as I observed a consistent
> reduction of boot time between e.g. 6.6.x and 6.12.x.
I am now partially in this discussion - what exactly are you trying to
achieve, or rather is there anything wrong with the current system? I am
trying to see whether there is something on my side to work on.
>
> > Best regards,
> >
> > Shankari
>
> Regards,
>
> Francesco
Ciao
Stephan
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-12-31 9:55 ` Stephan Müller
@ 2024-12-31 14:42 ` Francesco Valla
2025-01-02 9:06 ` Stephan Mueller
0 siblings, 1 reply; 26+ messages in thread
From: Francesco Valla @ 2024-12-31 14:42 UTC (permalink / raw)
To: Shankari, Stephan Müller; +Cc: Linux Embedded, Bird, Tim
Hi Stephan,
On Tuesday, 31 December 2024 at 10:55:06 Stephan Müller <smueller@chronox.de> wrote:
> Am Montag, 30. Dezember 2024, 23:35:03 Mitteleuropäische Normalzeit schrieb
> Francesco Valla:
>
> Hi Francesco,
>
> > Hi Shankari,
> >
> > On Sunday, 29 December 2024 at 19:52:29 Shankari <beingcap11@gmail.com>
> wrote:
> > > Hi
> > >
> > > I wanted to provide an update on my recent contributions to the BeaglePlay
> > > project. I have recently started contributing and have been analyzing the
> > > boot time of the init process. Below is the output from the system log:
> > >
> > > debian@BeaglePlay:~$ dmesg | grep "init process"
> > > [ 1.480490] Run /init as init process
> > >
> > > Moving forward, I plan to explore ways to modify the command line and
> > > further investigate the data used for SIG analysis. This will help me gain
> > > a deeper understanding of the boot process and its performance
> > > characteristics.
> >
> > I started the same journey around a week ago, and it's proving a valuable
> > experience.
> >
> > After some trimming, I reached a (reported) init startup time of around
> > 0.6s:
> >
> > root@beagleplay-ti:~# dmesg|grep /sbin
> > [ 0.630046] Run /sbin/init as init process
> >
> > The result above was obtained on a slightly modified 6.12.4 kernel with a
> > custom configuration (I am still thinking about the modifications, as they
> > are a bit unorthodox, but I can share them as well as the defconfig if you
> > are interested).
> >
> > > Please let me know if you have any suggestions or areas where I could
> > > focus
> > > my efforts.
> >
> > In general, I'd suggest to use a recent kernel, as I observed a consistent
> > reduction of boot time between e.g. 6.6.x and 6.12.x.
>
> I am now partially in this discussion - what exactly are you trying to
> achieve, or rather is there anything wrong with the current system? I am
> trying to see whether there is something on my side to work on.
>
The ultimate goal here is reducing the boot time to the minimum possible
without removing functionalities. The purpose is educational, but on the long
term it will probably be beneficial to my work too (as I work in the automotive
industry, where each millisecond counts).
There isn't anything inherently wrong, at the moment I am trying to determine
what is real initialization time and what instead is an actual waste of time
(e.g.: excessive probe deferral). The aforementioned jent_mod_init (on which
Tim I think is working on some level) is one of the longest single inits, but
to be honest I don't know much about all the entropy stuff.
Wishing you the best for the new year,
Francesco
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-12-31 14:42 ` Francesco Valla
@ 2025-01-02 9:06 ` Stephan Mueller
2025-01-02 10:33 ` Francesco Valla
0 siblings, 1 reply; 26+ messages in thread
From: Stephan Mueller @ 2025-01-02 9:06 UTC (permalink / raw)
To: Shankari, Francesco Valla; +Cc: Linux Embedded, Bird, Tim
Am Dienstag, 31. Dezember 2024, 15:42:16 CET schrieb Francesco Valla:
Hi Francesco,
> The ultimate goal here is reducing the boot time to the minimum possible
> without removing functionalities. The purpose is educational, but on the
> long term it will probably be beneficial to my work too (as I work in the
> automotive industry, where each millisecond counts).
>
> There isn't anything inherently wrong, at the moment I am trying to
> determine what is real initialization time and what instead is an actual
> waste of time (e.g.: excessive probe deferral). The aforementioned
> jent_mod_init (on which Tim I think is working on some level) is one of the
> longest single inits, but to be honest I don't know much about all the
> entropy stuff.
>
> Wishing you the best for the new year,
Same to you!
Thanks for your answer. With that, if you desire it, I can try to help you
lowering the boot time at least in light of the Jitter RNG. This, however,
requires a bit of analysis which you need to help me with as I do not have a
board you discuss. But the Jitter RNG has some turning knobs that can be used.
Ciao
Stephan
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2025-01-02 9:06 ` Stephan Mueller
@ 2025-01-02 10:33 ` Francesco Valla
2025-01-02 12:56 ` Stephan Mueller
0 siblings, 1 reply; 26+ messages in thread
From: Francesco Valla @ 2025-01-02 10:33 UTC (permalink / raw)
To: Shankari, Stephan Mueller; +Cc: Linux Embedded, Bird, Tim
Hi Stephan,
On Thursday, 2 January 2025 at 10:06:25 Stephan Mueller <smueller@chronox.de> wrote:
> Am Dienstag, 31. Dezember 2024, 15:42:16 CET schrieb Francesco Valla:
>
> Hi Francesco,
>
> > The ultimate goal here is reducing the boot time to the minimum possible
> > without removing functionalities. The purpose is educational, but on the
> > long term it will probably be beneficial to my work too (as I work in the
> > automotive industry, where each millisecond counts).
> >
> > There isn't anything inherently wrong, at the moment I am trying to
> > determine what is real initialization time and what instead is an actual
> > waste of time (e.g.: excessive probe deferral). The aforementioned
> > jent_mod_init (on which Tim I think is working on some level) is one of the
> > longest single inits, but to be honest I don't know much about all the
> > entropy stuff.
> >
> > Wishing you the best for the new year,
>
> Same to you!
>
> Thanks for your answer. With that, if you desire it, I can try to help you
> lowering the boot time at least in light of the Jitter RNG. This, however,
> requires a bit of analysis which you need to help me with as I do not have a
> board you discuss. But the Jitter RNG has some turning knobs that can be used.
>
> Ciao
> Stephan
>
That would be wonderful! Whenever you have the time, please let me know what
analysis you need.
Regards,
Francesco
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2025-01-02 10:33 ` Francesco Valla
@ 2025-01-02 12:56 ` Stephan Mueller
2025-01-03 17:23 ` Francesco Valla
2025-01-07 22:40 ` Bird, Tim
0 siblings, 2 replies; 26+ messages in thread
From: Stephan Mueller @ 2025-01-02 12:56 UTC (permalink / raw)
To: Shankari, Francesco Valla; +Cc: Linux Embedded, Bird, Tim
Am Donnerstag, 2. Januar 2025, 11:33:08 CET schrieb Francesco Valla:
Hi Francesco,
> That would be wonderful! Whenever you have the time, please let me know what
> analysis you need.
>
Ok, some background: the Jitter RNG technically has 2 noise sources which are
sampled concurrently:
1. variations of the execution of CPU instructions
2. variations of memory access times
For (1) the Jitter RNG has a fixed set of instructions it performs the
execution time measurements for: the SHA-3 conditioning operation
(specifically the Keccak sponge function). For that, it performs a given set
of Keccak operations.
For (2) the Jitter RNG allocates a fixed set of memory and simply reads /
writes data there and measures this timing.
For (1), the more instructions are samples, the higher the entropy gathered.
This means more time is required to sample that entropy. I.e. when you
increase the number of measured Keccak operations, you get more entropy.
For (2), when the memory is large enough to "spill over" into the next type of
memory (from L1 to L2 to L3 to RAM), the higher the entropy gathered.
So, for (2), to get more entropy, is invariant from the execution time. But
for (1), the entropy rate depends on the execution time.
Thus, what you want is to try to reduce the time spend for (1).
The key now is that the overall entropy rate the Jitter RNG requires for
functioning must be such that when gathering 256 bits of data from it, it
contains 256 bits of entropy.
Now, there are 2 "knobs" to turn via Kconfig:
- the oversampling rate (OSR): given that the individual number of rounds for
(1) and the number of accesses for (2) are kept the same, the OSR causes the
Jitter RNG to multiply the round counts. For example, the baseline with OSR ==
1 is that for gathering 256 bits of entropy, 256 times both noise sources are
sampled. For an OSR of, say, 3, to get 256 bits of entropy, 3 * 256 = 768
times both noise sources are sampled. This value was changed from 1 to 3 for
6.11 because there were reports on some CPUs that the Jitter RNG did not
produce sufficient entropy - most CPUs, however, can perfectly live with OSR
== 1.
- the amount of memory for (2) can be increased. The default is 2kBytes which
usually means that the L1 can fully handle the accesses.
======
Now given the description, what can you do? I would apply the following steps:
1. measure whether the timer your system has is really a high-res timer (the
higher the resolution, the higher the detected variations and thus the
entropy)
2. assuming that test 1 shows a high res timer, reduce the OSR back to 1
(CRYPTO_JITTERENTROPY_OSR) and measure the entropy rate -
3. if test 2 shows insufficient entropy, increase the amount of memory
(CRYPTO_JITTERENTROPY_MEMSIZE_*) and measure the entropy rate
The tool for measuring the entropy rate is given in [1] - check the README as
you need to enable a kernel config option to get an interface into the Jitter
RNG from user space. As you may not have the analysis tool, you may give the
data to me and I can analyze it.
More details on tuning the Jitter RNG is given in [2] - it discusses to the
user space variant, but applies to kernel as well.
[1] https://github.com/smuellerDD/jitterentropy-library/tree/master/tests/raw-entropy/recording_runtime_kernelspace
[2] https://github.com/smuellerDD/jitterentropy-library/tree/master/tests/raw-entropy#approach-to-solve-insufficient-entropy
Ciao
Stephan
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2025-01-02 12:56 ` Stephan Mueller
@ 2025-01-03 17:23 ` Francesco Valla
2025-01-04 15:45 ` Stephan Müller
2025-01-07 22:40 ` Bird, Tim
1 sibling, 1 reply; 26+ messages in thread
From: Francesco Valla @ 2025-01-03 17:23 UTC (permalink / raw)
To: Shankari, Stephan Mueller; +Cc: Linux Embedded, Bird, Tim
Hi Stephan,
On Thursday, 2 January 2025 at 13:56:59 Stephan Mueller <smueller@chronox.de> wrote:
> Am Donnerstag, 2. Januar 2025, 11:33:08 CET schrieb Francesco Valla:
>
> Hi Francesco,
>
> > That would be wonderful! Whenever you have the time, please let me know what
> > analysis you need.
> >
>
> Ok, some background: the Jitter RNG technically has 2 noise sources which are
> sampled concurrently:
>
> 1. variations of the execution of CPU instructions
>
> 2. variations of memory access times
>
> For (1) the Jitter RNG has a fixed set of instructions it performs the
> execution time measurements for: the SHA-3 conditioning operation
> (specifically the Keccak sponge function). For that, it performs a given set
> of Keccak operations.
>
> For (2) the Jitter RNG allocates a fixed set of memory and simply reads /
> writes data there and measures this timing.
>
>
> For (1), the more instructions are samples, the higher the entropy gathered.
> This means more time is required to sample that entropy. I.e. when you
> increase the number of measured Keccak operations, you get more entropy.
>
> For (2), when the memory is large enough to "spill over" into the next type of
> memory (from L1 to L2 to L3 to RAM), the higher the entropy gathered.
>
>
> So, for (2), to get more entropy, is invariant from the execution time. But
> for (1), the entropy rate depends on the execution time.
>
>
> Thus, what you want is to try to reduce the time spend for (1).
>
>
> The key now is that the overall entropy rate the Jitter RNG requires for
> functioning must be such that when gathering 256 bits of data from it, it
> contains 256 bits of entropy.
>
>
> Now, there are 2 "knobs" to turn via Kconfig:
>
> - the oversampling rate (OSR): given that the individual number of rounds for
> (1) and the number of accesses for (2) are kept the same, the OSR causes the
> Jitter RNG to multiply the round counts. For example, the baseline with OSR ==
> 1 is that for gathering 256 bits of entropy, 256 times both noise sources are
> sampled. For an OSR of, say, 3, to get 256 bits of entropy, 3 * 256 = 768
> times both noise sources are sampled. This value was changed from 1 to 3 for
> 6.11 because there were reports on some CPUs that the Jitter RNG did not
> produce sufficient entropy - most CPUs, however, can perfectly live with OSR
> == 1.
>
> - the amount of memory for (2) can be increased. The default is 2kBytes which
> usually means that the L1 can fully handle the accesses.
>
>
This was a very instructive read. I didn't (yet?) have the time to dive deep
into all the crypto "backbone", but I think I understood in broad terms.
Thank you!
> ======
>
>
> Now given the description, what can you do? I would apply the following steps:
>
> 1. measure whether the timer your system has is really a high-res timer (the
> higher the resolution, the higher the detected variations and thus the
> entropy)
>
Resolution reported by clock_getres() is 1ns. Is this sufficient?
> 2. assuming that test 1 shows a high res timer, reduce the OSR back to 1
> (CRYPTO_JITTERENTROPY_OSR) and measure the entropy rate -
>
Turned out my system already had the OSR set to 1, since CONFIG_CRYPTO_FIPS was
set to N.
> 3. if test 2 shows insufficient entropy, increase the amount of memory
> (CRYPTO_JITTERENTROPY_MEMSIZE_*) and measure the entropy rate
>
>
>
> The tool for measuring the entropy rate is given in [1] - check the README as
> you need to enable a kernel config option to get an interface into the Jitter
> RNG from user space. As you may not have the analysis tool, you may give the
> data to me and I can analyze it.
>
Here are the results (with default parameters for processdata.sh:
Opening file: '../results-analysis-runtime/raw_noise.0Fbitout.data' (SHA-256 hash 079f14467f309991a0bcaac2b667283ff1f19eba0ddf1fbd6b34e55a6d94ed87)
Loaded 1000000 samples of 16 distinct 4-bit-wide symbols
Number of Binary Symbols: 4000000
Running non-IID tests...
Running Most Common Value Estimate...
Bitstring MCV Estimate: mode = 2027350, p-hat = 0.50683750000000005, p_u = 0.50748139719173813
Most Common Value Estimate (bit string) = 0.978573 / 1 bit(s)
Literal MCV Estimate: mode = 68652, p-hat = 0.068652000000000005, p_u = 0.069303328207377918
Most Common Value Estimate = 3.850932 / 4 bit(s)
Running Entropic Statistic Estimates (bit strings only)...
Bitstring Collision Estimate: X-bar = 2.4981538638330933, sigma-hat = 0.49999674790330145, p = 0.53784137679559285
Collision Test Estimate (bit string) = 0.894747 / 1 bit(s)
Bitstring Markov Estimate: P_0 = 0.50683750000000005, P_1 = 0.49316249999999995, P_0,0 = 0.50927960145016893, P_0,1 = 0.49072039854983107, P_1,0 = 0.50432742976576173, P_1,1 = 0.49567257023423827, p_max = 3.0783392443248932e-38
Markov Test Estimate (bit string) = 0.973524 / 1 bit(s)
Bitstring Compression Estimate: X-bar = 5.2062336468660613, sigma-hat = 1.0200139851715606, p = 0.037082666137132736
Compression Test Estimate (bit string) = 0.792185 / 1 bit(s)
Running Tuple Estimates...
Bitstring t-Tuple Estimate: t = 18, p-hat_max = 0.5303003556530639666278, p_u = 0.5309431295223588315809
Bitstring LRS Estimate: u = 19, v = 43, p-hat = 0.50389349457067132, p_u = 0.50453743245287026
T-Tuple Test Estimate (bit string) = 0.913371 / 1 bit(s)
Literal t-Tuple Estimate: t = 4, p-hat_max = 0.0814448250695374631388, p_u = 0.08214935860193944897723
Literal LRS Estimate: u = 5, v = 9, p-hat = 0.063061514307713893, p_u = 0.063687630641525933
T-Tuple Test Estimate = 3.605607 / 4 bit(s)
LRS Test Estimate (bit string) = 0.986967 / 1 bit(s)
LRS Test Estimate = 3.972843 / 4 bit(s)
Running Predictor Estimates...
Bitstring MultiMCW Prediction Estimate: N = 3999937, Pglobal' = 0.50734663518092882 (C = 2026779) Plocal can't affect result (r = 25)
Multi Most Common in Window (MultiMCW) Prediction Test Estimate (bit string) = 0.978956 / 1 bit(s)
Literal MultiMCW Prediction Estimate: N = 999937, Pglobal' = 0.071847840262787413 (C = 71181) Plocal can't affect result (r = 6)
Multi Most Common in Window (MultiMCW) Prediction Test Estimate = 3.798911 / 4 bit(s)
Bitstring Lag Prediction Estimate: N = 3999999, Pglobal' = 0.50760302185063 (C = 2027836) Plocal can't affect result (r = 23)
Lag Prediction Test Estimate (bit string) = 0.978227 / 1 bit(s)
Literal Lag Prediction Estimate: N = 999999, Pglobal' = 0.07177509499573978 (C = 71113) Plocal can't affect result (r = 6)
Lag Prediction Test Estimate = 3.800373 / 4 bit(s)
Bitstring MultiMMC Prediction Estimate: N = 3999998, Pglobal' = 0.50910236964447519 (C = 2033833) Plocal can't affect result (r = 23)
Multi Markov Model with Counting (MultiMMC) Prediction Test Estimate (bit string) = 0.973972 / 1 bit(s)
Literal MultiMMC Prediction Estimate: N = 999998, Pglobal' = 0.06979561605633619 (C = 69142) Plocal can't affect result (r = 6)
Multi Markov Model with Counting (MultiMMC) Prediction Test Estimate = 3.840720 / 4 bit(s)
Bitstring LZ78Y Prediction Estimate: N = 3999983, Pglobal' = 0.50745980290740611 (C = 2027255) Plocal can't affect result (r = 25)
LZ78Y Prediction Test Estimate (bit string) = 0.978635 / 1 bit(s)
Literal LZ78Y Prediction Estimate: N = 999983, Pglobal' = 0.068264919012970812 (C = 67617) Plocal can't affect result (r = 5)
LZ78Y Prediction Test Estimate = 3.872712 / 4 bit(s)
H_original: 3.605607
H_bitstring: 0.792185
min(H_original, 4 X H_bitstring): 3.168741
---
Opening file: '../results-analysis-runtime/raw_noise.FFbitout.data' (SHA-256 hash 670cc4f908a3fa430112387c7490280b801fbc3e0d9b2eb5725a7382f1726353)
Loaded 1000000 samples of 256 distinct 8-bit-wide symbols
Number of Binary Symbols: 8000000
Running non-IID tests...
Running Most Common Value Estimate...
Bitstring MCV Estimate: mode = 4293572, p-hat = 0.53669650000000002, p_u = 0.53715061859478275
Most Common Value Estimate (bit string) = 0.896601 / 1 bit(s)
Literal MCV Estimate: mode = 25394, p-hat = 0.025394, p_u = 0.025799226085884197
Most Common Value Estimate = 5.276528 / 8 bit(s)
Running Entropic Statistic Estimates (bit strings only)...
Bitstring Collision Estimate: X-bar = 2.4368621131861672, sigma-hat = 0.4959976634888219, p = 0.67866590835207607
Collision Test Estimate (bit string) = 0.559227 / 1 bit(s)
Bitstring Markov Estimate: P_0 = 0.53669650000000002, P_1 = 0.46330349999999998, P_0,0 = 0.58912975024059222, P_0,1 = 0.41087024975940778, P_1,0 = 0.47595730335441655, P_1,1 = 0.52404269664558345, p_max = 3.5198162547162731e-30
Markov Test Estimate (bit string) = 0.764393 / 1 bit(s)
Bitstring Compression Estimate: X-bar = 5.1060913378184907, sigma-hat = 1.0602301402207321, p = 0.089700342434675784
Compression Test Estimate (bit string) = 0.579790 / 1 bit(s)
Running Tuple Estimates...
Bitstring t-Tuple Estimate: t = 24, p-hat_max = 0.6077535669643823323526, p_u = 0.608198213970942755998
Bitstring LRS Estimate: u = 25, v = 55, p-hat = 0.57377327555229816, p_u = 0.57422363845508301
T-Tuple Test Estimate (bit string) = 0.717387 / 1 bit(s)
Literal t-Tuple Estimate: t = 2, p-hat_max = 0.02539400000000000000072, p_u = 0.02579922608588419654918
Literal LRS Estimate: u = 3, v = 6, p-hat = 0.014678019585973216, p_u = 0.014987790126594754
T-Tuple Test Estimate = 5.276528 / 8 bit(s)
LRS Test Estimate (bit string) = 0.800315 / 1 bit(s)
LRS Test Estimate = 6.060069 / 8 bit(s)
Running Predictor Estimates...
Bitstring MultiMCW Prediction Estimate: N = 7999937, Pglobal' = 0.53749557635492473 (C = 4296298) Plocal can't affect result (r = 26)
Multi Most Common in Window (MultiMCW) Prediction Test Estimate (bit string) = 0.895675 / 1 bit(s)
Literal MultiMCW Prediction Estimate: N = 999937, Pglobal' = 0.031150330241116859 (C = 30704) Plocal can't affect result (r = 4)
Multi Most Common in Window (MultiMCW) Prediction Test Estimate = 5.004609 / 8 bit(s)
Bitstring Lag Prediction Estimate: N = 7999999, Pglobal' = 0.55941498930539801 (C = 4471702) Plocal can't affect result (r = 30)
Lag Prediction Test Estimate (bit string) = 0.838009 / 1 bit(s)
Literal Lag Prediction Estimate: N = 999999, Pglobal' = 0.024834737018808978 (C = 24437) Plocal can't affect result (r = 4)
Lag Prediction Test Estimate = 5.331497 / 8 bit(s)
Bitstring MultiMMC Prediction Estimate: N = 7999998, Pglobal' = 0.56384793754105667 (C = 4507169) Plocal can't affect result (r = 30)
Multi Markov Model with Counting (MultiMMC) Prediction Test Estimate (bit string) = 0.826622 / 1 bit(s)
Literal MultiMMC Prediction Estimate: N = 999998, Pglobal' = 0.026034084289744124 (C = 25627) Plocal can't affect result (r = 4)
Multi Markov Model with Counting (MultiMMC) Prediction Test Estimate = 5.263455 / 8 bit(s)
Bitstring LZ78Y Prediction Estimate: N = 7999983, Pglobal' = 0.55942260687547074 (C = 4471754) Plocal can't affect result (r = 30)
LZ78Y Prediction Test Estimate (bit string) = 0.837990 / 1 bit(s)
Literal LZ78Y Prediction Estimate: N = 999983, Pglobal' = 0.026039513473967817 (C = 25632) Plocal can't affect result (r = 4)
LZ78Y Prediction Test Estimate = 5.263154 / 8 bit(s)
H_original: 5.004609
H_bitstring: 0.559227
min(H_original, 8 X H_bitstring): 4.473812
---
>
> More details on tuning the Jitter RNG is given in [2] - it discusses to the
> user space variant, but applies to kernel as well.
>
> [1] https://github.com/smuellerDD/jitterentropy-library/tree/master/tests/raw-entropy/recording_runtime_kernelspace
>
> [2] https://github.com/smuellerDD/jitterentropy-library/tree/master/tests/raw-entropy#approach-to-solve-insufficient-entropy
>
> Ciao
> Stephan
>
Thank you again!
Francesco
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2025-01-03 17:23 ` Francesco Valla
@ 2025-01-04 15:45 ` Stephan Müller
0 siblings, 0 replies; 26+ messages in thread
From: Stephan Müller @ 2025-01-04 15:45 UTC (permalink / raw)
To: Shankari, Francesco Valla; +Cc: Linux Embedded, Bird, Tim
Am Freitag, 3. Januar 2025, 18:23:19 Mitteleuropäische Normalzeit schrieb
Francesco Valla:
Hi Francesco,
> > ======
> >
> >
> > Now given the description, what can you do? I would apply the following
> > steps:
> >
> > 1. measure whether the timer your system has is really a high-res timer
> > (the higher the resolution, the higher the detected variations and thus
> > the entropy)
>
> Resolution reported by clock_getres() is 1ns. Is this sufficient?
>
It should, but it is in relationship to the complexity of the CPU itself.
> > 2. assuming that test 1 shows a high res timer, reduce the OSR back to 1
> > (CRYPTO_JITTERENTROPY_OSR) and measure the entropy rate -
>
> Turned out my system already had the OSR set to 1, since CONFIG_CRYPTO_FIPS
> was set to N.
>
> > 3. if test 2 shows insufficient entropy, increase the amount of memory
> > (CRYPTO_JITTERENTROPY_MEMSIZE_*) and measure the entropy rate
> >
> >
> >
> > The tool for measuring the entropy rate is given in [1] - check the README
> > as you need to enable a kernel config option to get an interface into the
> > Jitter RNG from user space. As you may not have the analysis tool, you
> > may give the data to me and I can analyze it.
>
> Here are the results (with default parameters for processdata.sh:
>
...
> min(H_original, 4 X H_bitstring): 3.168741
That last value, the min-value, is the key: it must be larger than 1/OSR -
when it gets close to 1/OSR, the health tests start to flag errors once in a
while (with a probability rate of around 2**-30 time stamps). So, you have OSR
set to 1 which is already the lowest value supported by the Jitter RNG. Thus,
there is unfortunately not much more you can do to increase the performance
during boot time.
I thought OSR was set to 3 in your environment.
> min(H_original, 8 X H_bitstring): 4.473812
Ciao
Stephan
^ permalink raw reply [flat|nested] 26+ messages in thread
* RE: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2024-12-30 22:22 ` [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Francesco Valla
@ 2025-01-07 21:27 ` Bird, Tim
0 siblings, 0 replies; 26+ messages in thread
From: Bird, Tim @ 2025-01-07 21:27 UTC (permalink / raw)
To: Francesco Valla, Linux Embedded; +Cc: smueller@chronox.de
> -----Original Message-----
> From: Francesco Valla <francesco@valla.it>
>
> On Tuesday, 3 December 2024 at 22: 24: 28 Bird, Tim <Tim. Bird@ sony. com> wrote: > > -----Original Message----- > > From: Francesco
> Valla <francesco@ valla. it>
> On Tuesday, 3 December 2024 at 22:24:28 Bird, Tim <Tim.Bird@sony.com> wrote:
> > > -----Original Message-----
> > > From: Francesco Valla <francesco@valla.it>
> > > Dear fellow boot time optimizers,
> > >
...
> > > Here is a python script which can analyze a dmesg output with initcall_debug
> > > option enabled and extract some useful information. It can for example be used
> > > to analyze the output of the grab-boot-data.sh tool that Tim presented on this
> > > list [1] just a few days ago.
> > >
> > > Usage is very simple, as the output of dmesg can be piped directly to it:
> > >
> > > dmesg | analyze-initcall-debug.py
> > >
> > > If no option is specified, it outputs a brief summary, like the following one
> > > (obtained on my Beagleplay):
> > >
> > > 1758 drivers has been initialized, of which 1758 before userspace
> > > 119 probes happened outside of the init of their driver
> > > 0 deferred probes pending
> > > ---
> > > Top 10 init/probes durations:
> > > * 30200000.dss -> 523002us
> > > * deferred_probe_initcall -> 487483us
> > > * fd00000.gpu -> 162859us
> > > * 8000f00.mdio -> 142521us
> > > * 44043000.system-controller -> 71390us
> > > * 2-004c -> 71178us
> > > * 40900000.crypto -> 59350us
> > > * 8000000.ethernet -> 58419us
> > > * 44043000.system-controller:clock-controller -> 56599us
> > > * jent_mod_init -> 52140us
> >
> > This is odd. On my beagleplay board, jent_mod_init only took 32326us.
> > (see https://birdcloud.org/boot-time-files/boot-data-timslab-bp1-241203-134136.txt)
> >
> > I'm assuming that we have similar hardware, but possibly different configs,
> > kernel cmdlines or kernel versions. I'll take a look at this and see if I can
> > figure out what the difference is between our systems, that causes the
> > difference in the duration for this function.
> >
> > This initcall (jent_mod_init) is on my list of initcalls to research to see if they
> > can be improved or deferred. I haven't seen any degradation in system
> > behavior by deferring this initcall on my system, but that could be from
> > lack of my system doing some related operation that needs the RNG data, or my
> > own ignorance of the effects of this call.
> >
> > Can someone comment on what items or operations might depend on jent_mod_init
> > in early boot? In particular, would we expect any cryptographic problems if
> > the initcall was deferred to a few seconds after booting?
> >
> > It can be configured as a module, which makes me think that maybe loading
> > it sometime in very late boot (or even later) is OK.
> >
> > jent_mod_init is defined in crypto/jitterentropy-kcapi.c, and controlled by
> > CONFIG_CRYPTO_JITTERENTROPY (See crypto/Kconfig)
> >
> > It appears to do some random number generator seeding by measuring
> > the jitter of a compressiong operation in the kernel. I assume some of the cryptography
> > configs affect the duration of the operations. The initcall duration results on
> > my beagleplay seem to be relatively consistent (in the 32ms range consistently),
> > and from bobs_lab, on machine sam1, the duration range is also consistent
> > (at between 4800 and 5200 usecs).
> >
> > I'd be interested to see if the range is consistent between runs on other machines
> >
> > Francesco - Can you submit another boot-data file (or 2 or 3) for francsecoslab-beagleplay, to
> > provide some data on this?
> >
>
> I actually lost this request and only found it this morning when reviewing past
> emails. My apologies.
>
> Anyway: I just uploaded another boot-data file (of a kernel with some
> optimizations), but can confirm that the time spent inside jent_mod_init across
> multiple runs appears consistent - or should I say fixed? - at 52ms.
Thanks. This is very useful. I appreciate you following up on this.
-- Tim
^ permalink raw reply [flat|nested] 26+ messages in thread
* boot markers ideas (was RE: [boot-time] jent_mod_init on beagleplay)
2024-12-30 22:35 ` Francesco Valla
2024-12-31 9:55 ` Stephan Müller
@ 2025-01-07 21:42 ` Bird, Tim
2025-01-07 23:40 ` Rob Landley
1 sibling, 1 reply; 26+ messages in thread
From: Bird, Tim @ 2025-01-07 21:42 UTC (permalink / raw)
To: Francesco Valla, Stephan Mueller, Shankari; +Cc: Linux Embedded
> -----Original Message-----
> From: Francesco Valla <francesco@valla.it>
...
> > I wanted to provide an update on my recent contributions to the BeaglePlay
> > project. I have recently started contributing and have been analyzing the
> > boot time of the init process. Below is the output from the system log:
> >
> > debian@BeaglePlay:~$ dmesg | grep "init process"
> > [ 1.480490] Run /init as init process
> >
...
>
> I started the same journey around a week ago, and it's proving a valuable
> experience.
>
> After some trimming, I reached a (reported) init startup time of around 0.6s:
>
> root@beagleplay-ti:~# dmesg|grep /sbin
> [ 0.630046] Run /sbin/init as init process
I'm starting to think that we should be using this particular kernel message
as a consistent "boot marker" for kernel startup time. It's certainly not the
end of when the kernel is doing stuff on startup, but I do believe it marks
one of the important transition points (start of user space activity), and
it seems to be ubiquitously reported.
At Plumbers, I had proposed to introduce a set of specific instrumentation
points in the kernel and use those as key checkpoints. But IMHO it's good
to use existing printk messages where possible, since they're already present - no
additional instrumentation needed.
I'm going to do some additional research on how consistently other printk strings
show up in dmesg boot reports, to see if there are some other strings
that can be used a boot markers, or if it would still make sense to introduce some.
I think a boot marker for the start of each initcall phase is probably useful.
Thanks for these reports of the timestamps for the "init process" strings.
-- Tim
^ permalink raw reply [flat|nested] 26+ messages in thread
* RE: [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output
2025-01-02 12:56 ` Stephan Mueller
2025-01-03 17:23 ` Francesco Valla
@ 2025-01-07 22:40 ` Bird, Tim
1 sibling, 0 replies; 26+ messages in thread
From: Bird, Tim @ 2025-01-07 22:40 UTC (permalink / raw)
To: Stephan Mueller, Shankari, Francesco Valla; +Cc: Linux Embedded
> -----Original Message-----
> From: Stephan Mueller <smueller@chronox.de>
> Am Donnerstag, 2. Januar 2025, 11:33:08 CET schrieb Francesco Valla:
>
> Hi Francesco,
>
> > That would be wonderful! Whenever you have the time, please let me know what
> > analysis you need.
> >
>
> Ok, some background: the Jitter RNG technically has 2 noise sources which are
> sampled concurrently:
>
> 1. variations of the execution of CPU instructions
>
> 2. variations of memory access times
>
> For (1) the Jitter RNG has a fixed set of instructions it performs the
> execution time measurements for: the SHA-3 conditioning operation
> (specifically the Keccak sponge function). For that, it performs a given set
> of Keccak operations.
>
> For (2) the Jitter RNG allocates a fixed set of memory and simply reads /
> writes data there and measures this timing.
>
>
> For (1), the more instructions are samples, the higher the entropy gathered.
> This means more time is required to sample that entropy. I.e. when you
> increase the number of measured Keccak operations, you get more entropy.
>
> For (2), when the memory is large enough to "spill over" into the next type of
> memory (from L1 to L2 to L3 to RAM), the higher the entropy gathered.
>
>
> So, for (2), to get more entropy, is invariant from the execution time. But
> for (1), the entropy rate depends on the execution time.
>
>
> Thus, what you want is to try to reduce the time spend for (1).
>
>
> The key now is that the overall entropy rate the Jitter RNG requires for
> functioning must be such that when gathering 256 bits of data from it, it
> contains 256 bits of entropy.
>
>
> Now, there are 2 "knobs" to turn via Kconfig:
>
> - the oversampling rate (OSR): given that the individual number of rounds for
> (1) and the number of accesses for (2) are kept the same, the OSR causes the
> Jitter RNG to multiply the round counts. For example, the baseline with OSR ==
> 1 is that for gathering 256 bits of entropy, 256 times both noise sources are
> sampled. For an OSR of, say, 3, to get 256 bits of entropy, 3 * 256 = 768
> times both noise sources are sampled. This value was changed from 1 to 3 for
> 6.11 because there were reports on some CPUs that the Jitter RNG did not
> produce sufficient entropy - most CPUs, however, can perfectly live with OSR
> == 1.
>
> - the amount of memory for (2) can be increased. The default is 2kBytes which
> usually means that the L1 can fully handle the accesses.
Very interesting. Thanks.
>
>
> ======
>
>
> Now given the description, what can you do? I would apply the following steps:
>
> 1. measure whether the timer your system has is really a high-res timer (the
> higher the resolution, the higher the detected variations and thus the
> entropy)
>
> 2. assuming that test 1 shows a high res timer, reduce the OSR back to 1
> (CRYPTO_JITTERENTROPY_OSR) and measure the entropy rate -
>
> 3. if test 2 shows insufficient entropy, increase the amount of memory
> (CRYPTO_JITTERENTROPY_MEMSIZE_*) and measure the entropy rate
>
>
>
> The tool for measuring the entropy rate is given in [1] - check the README as
> you need to enable a kernel config option to get an interface into the Jitter
> RNG from user space. As you may not have the analysis tool, you may give the
> data to me and I can analyze it.
>
>
> More details on tuning the Jitter RNG is given in [2] - it discusses to the
> user space variant, but applies to kernel as well.
>
> [1] https://github.com/smuellerDD/jitterentropy-library/tree/master/tests/raw-entropy/recording_runtime_kernelspace
>
> [2] https://github.com/smuellerDD/jitterentropy-library/tree/master/tests/raw-entropy#approach-to-solve-insufficient-entropy
First - sorry for the slow response. I'm just getting back from the holidays.
And now... Wow! thanks for that detailed response. I will dive into your response a bit
deeper, soon, to try to analyze how it may affect our approach. But let me back up a bit
and describe our overall approach.
I think Francesco answered your query about what we are trying to do here, and what we
want from you very well. Let me add a bit of context, and some more thoughts.
In general, when trying to improve boot time, we look at 3 general techniques:
1. remove something
2. defer something
3. optimize something
Some of the work in optimizing Linux for embedded is finding kernel features that are not
needed at all for a particular use case, and just removing them (usually via the kernel config,
but sometimes via a command line option). Other times, a feature may be desirable, but
the critical capability that must come up quickly (like a camera) does not depend on that
item. In that case, we can defer the loading of a feature until after the critical capability is
operational and there is no harm done.
Finally, some times it may be possible to optimize the initialization of something, so it
takes less time (by using pre-calculated values, or optimizing the initialization process).
When deferring the initialization of a feature, sometimes it is possible to break it up
into parts, such that only the most critical part is initialized first, and the rest of it can
be initialized later.
In the case of jent_mod_init, I have a few ideas that I'd like to investigate, and your expertise
with the driver is very helpful to see which things make sense and which don't.
First, I've deferred loading the jitter entropy module, by telling the kernel to defer its initcall
(using an out-of-tree patch). That works to eliminate the cost of jent_mod_init during
the critical boot phase. Another method might be to just load the jitter entropy module
sometime later in the boot sequence. To be honest, this approach, while effective at booting
more quickly, makes me nervous because it means that the RNG is not properly seeded
(if that's the correct term), until possibly a few seconds after boot. If nothing uses the entropy
before then, I don't see a problem. But there may be flows of the entropy data or RNG values
data at kernel startup time that I'm not aware of. And I don't want to break security for
the kernel by being sloppy.
So my first question would be: how bad is it for the RNG if the entropy it not collected
until a few seconds after booting?
Related to this would be: Do you have an idea which things are using the RNG in early boot
that would be affected by a temporary lack of initialization of entropy? Or is it possible to monitor
the use of the RNG, to get a report of possibly affected RNG users?
Another idea I've had is this - could we save some entropy from a previous
boot, to pre-seed the RNG, to avoid having jent_mod_init do it's entropy gathering?
My idea would be something like this: check if there's existing entropy from a previous
boot, and if so seed the RNG from that (and wipe out the data from the previous boot).
If there isn't entropy from a previous boot, work as currently designed to gather the
entropy from the measurements for the current boot.
I'm working on general mechanisms to transfer data from a previous kernel runtime instantiation
to the next, but this particular transfer would involve saving some entropy to some kind
of persistent storage on machine shutdown. (Right now I'm looking at using the bootconfig
mechanism store the data and re-convey it to a newly booting kernel instance).
There are, of course, some security ramifications to this approach as well. Trusting the
saved data has its own issues.
I would be interested to hear your thoughts on this. How much data would need to be transferred?
Would loading the data, parsing it, and injecting it ultimately consume more time than
the generation of the data? We are, after all, only talking about ~50ms here.
Note that this ability to capture information from one boot, and convey it to a subsequent
boot is a feature that I plan to work on independent of this specific scenario.
Anyway, I hope that this answers some questions.
Thanks for any additional insights you can provide.
-- Tim
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: boot markers ideas (was RE: [boot-time] jent_mod_init on beagleplay)
2025-01-07 21:42 ` boot markers ideas (was RE: [boot-time] jent_mod_init on beagleplay) Bird, Tim
@ 2025-01-07 23:40 ` Rob Landley
2025-01-09 16:23 ` Francesco Valla
0 siblings, 1 reply; 26+ messages in thread
From: Rob Landley @ 2025-01-07 23:40 UTC (permalink / raw)
To: Bird, Tim, Francesco Valla, Stephan Mueller, Shankari; +Cc: Linux Embedded
On 1/7/25 15:42, Bird, Tim wrote:
>
>
>> -----Original Message-----
>> From: Francesco Valla <francesco@valla.it>
> ...
>>> I wanted to provide an update on my recent contributions to the BeaglePlay
>>> project. I have recently started contributing and have been analyzing the
>>> boot time of the init process. Below is the output from the system log:
>>>
>>> debian@BeaglePlay:~$ dmesg | grep "init process"
>>> [ 1.480490] Run /init as init process
>>>
> ...
>
>>
>> I started the same journey around a week ago, and it's proving a valuable
>> experience.
>>
>> After some trimming, I reached a (reported) init startup time of around 0.6s:
>>
>> root@beagleplay-ti:~# dmesg|grep /sbin
>> [ 0.630046] Run /sbin/init as init process
>
>
> I'm starting to think that we should be using this particular kernel message
> as a consistent "boot marker" for kernel startup time. It's certainly not the
> end of when the kernel is doing stuff on startup, but I do believe it marks
> one of the important transition points (start of user space activity), and
> it seems to be ubiquitously reported.
>
> At Plumbers, I had proposed to introduce a set of specific instrumentation
> points in the kernel and use those as key checkpoints. But IMHO it's good
> to use existing printk messages where possible, since they're already present - no
> additional instrumentation needed.
Is there a place to get this measuring script other than fishing it out
of a webmail archive?
https://www.spinics.net/lists/linux-embedded/msg04363.html
The most recent wiki mention in the archive subject lines was
https://www.spinics.net/lists/linux-embedded/msg04336.html and trying to
find this effort in elinux.org's top right search bar found
https://elinux.org/Boot-up_Time_Reduction_Howto which "view history"
says was last touched in 2010...
Rob
P.S. Meanwhile, python 3 goes in quite the opposite direction:
https://landley.net/notes-2024.html#09-04-2024
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: boot markers ideas (was RE: [boot-time] jent_mod_init on beagleplay)
2025-01-07 23:40 ` Rob Landley
@ 2025-01-09 16:23 ` Francesco Valla
0 siblings, 0 replies; 26+ messages in thread
From: Francesco Valla @ 2025-01-09 16:23 UTC (permalink / raw)
To: Bird, Tim, Stephan Mueller, Shankari, Rob Landley; +Cc: Linux Embedded
Hello Rob,
On Wednesday, 8 January 2025 at 00:40:13 Rob Landley <rob@landley.net> wrote:
> Is there a place to get this measuring script other than fishing it out
> of a webmail archive?
>
> https://www.spinics.net/lists/linux-embedded/msg04363.html
No, at the moment the mailing list is the only place I posted it. I am still
unsure if it should live on its own somewhere or it's better to try to augment
the bootchart.py script that lives inside the kernel sources [1].
> The most recent wiki mention in the archive subject lines was
> https://www.spinics.net/lists/linux-embedded/msg04336.html and trying to
> find this effort in elinux.org's top right search bar found
> https://elinux.org/Boot-up_Time_Reduction_Howto which "view history"
> says was last touched in 2010...
>
> Rob
>
[1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/tools/power/pm-graph/bootgraph.py
Regards,
Francesco
^ permalink raw reply [flat|nested] 26+ messages in thread
end of thread, other threads:[~2025-01-09 17:13 UTC | newest]
Thread overview: 26+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2024-11-27 23:35 [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Francesco Valla
2024-12-03 20:33 ` Bird, Tim
2024-12-05 12:57 ` Francesco Valla
2024-12-05 14:58 ` Geert Uytterhoeven
2024-12-05 21:36 ` Francesco Valla
2024-12-09 3:10 ` [RFC PATCH] boot-time: instrument probes more Bird, Tim
2024-12-21 14:47 ` Francesco Valla
2024-12-29 17:45 ` Francesco Valla
2024-12-03 21:24 ` [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Bird, Tim
2024-12-05 7:02 ` Stephan Mueller
[not found] ` <CAORPcfUfgNnQb6m0baW9qEGnrGYsnbpvwUUmF5Y9Byh9_iMAZw@mail.gmail.com>
2024-12-30 22:35 ` Francesco Valla
2024-12-31 9:55 ` Stephan Müller
2024-12-31 14:42 ` Francesco Valla
2025-01-02 9:06 ` Stephan Mueller
2025-01-02 10:33 ` Francesco Valla
2025-01-02 12:56 ` Stephan Mueller
2025-01-03 17:23 ` Francesco Valla
2025-01-04 15:45 ` Stephan Müller
2025-01-07 22:40 ` Bird, Tim
2025-01-07 21:42 ` boot markers ideas (was RE: [boot-time] jent_mod_init on beagleplay) Bird, Tim
2025-01-07 23:40 ` Rob Landley
2025-01-09 16:23 ` Francesco Valla
2024-12-30 22:22 ` [boot-time] jent_mod_init on beagleplay (was RE: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output Francesco Valla
2025-01-07 21:27 ` Bird, Tim
2024-12-04 0:29 ` Bird, Tim
2024-12-05 13:05 ` Francesco Valla
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).