For all of you who are bothered by the performance of udev:
I did some profiling, where udev spents its time... so here are the numbers:
Out of 3.63s of measured activity udev spent:
44.1% (1,6s) with /sbin/modprobe 13.3% (0,48s) with persistent-storage (mostly vol_id) 12% (0.44s) with 60-net.rules 10.5% (0.38s) with 90-alsa.rules 7% (0.25s) with pam_console (which will go away anyway)
Your numbers may vary because of different hardware.
Harald Hoyer schrieb:
44.1% (1,6s) with /sbin/modprobe
modprobe is parsing its configuration/dependency files every time it is called.
12% (0.44s) with 60-net.rules
I am sure 60-net.rules does not have to call /etc/sysconfig/network-scripts/net.hotplug for _every_ "net" event.
Ralf Ertzinger wrote:
Hi.
On Tue, 11 Sep 2007 15:55:25 +0200, Harald Hoyer wrote:
modprobe is parsing its configuration/dependency files every time it is called.
What else should it do?
Cache the result in a dump of the resulting binary structs in disk (ugly). Or much better: have a run as daemon mode where one can stuff new modules names to probe to it through a pipe, that would avoid a zillion forks and execs too, or maybe split most of the code into a lib and use that lib from udev?
Regards,
Hans
On Tue, 2007-09-11 at 16:02 +0200, Hans de Goede wrote:
Ralf Ertzinger wrote:
Hi.
On Tue, 11 Sep 2007 15:55:25 +0200, Harald Hoyer wrote:
modprobe is parsing its configuration/dependency files every time it is called.
What else should it do?
Cache the result in a dump of the resulting binary structs in disk (ugly). Or much better: have a run as daemon mode where one can stuff new modules names to probe to it through a pipe, that would avoid a zillion forks and execs too,
or maybe split most of the code into a lib and use that lib from udev?
I kind of like this last option myself. You don't really want to dupe the modprobe code in udev, and have two separate code bases to maintain. I don't really see a need for a daemon since 99% of modloads are done upon boot, plus now you have a pipe/socket/whatever to load mods and the security implications that has. Making libmodprobe.so that they all use, centralized code-base and all of that just seems to make some good sense.
On Tue, 2007-09-11 at 16:02 +0200, Hans de Goede wrote:
Or much better: have a run as daemon mode where one can stuff new modules names to probe to it through a pipe, that would avoid a zillion forks and execs too, or maybe split most of the code into a lib and use that lib from udev?
Came to the same conclusion, as well. Add three options: 1) start the daemon, 2) communicate with the daemon, and 3) kill daemon. Processes should really be as reusable as code. The daemon just has to be made sensitive to configuration changes, or document somewhere that the daemon cached information remains static for the entire session. --
Richi Plana
Hi.
On Tue, 11 Sep 2007 16:02:14 +0200, Hans de Goede wrote
Cache the result in a dump of the resulting binary structs in disk (ugly).
Or let depmod create a more easily parseable format on the disk (as Jakub suggested).
Or much better: have a run as daemon mode where one can stuff new modules names to probe to it through a pipe, that would avoid a zillion forks and execs too
Daemons create a bunch of new security problems we really do not want to have at that place.
Ralf Ertzinger wrote:
Hi.
On Tue, 11 Sep 2007 16:02:14 +0200, Hans de Goede wrote
Cache the result in a dump of the resulting binary structs in disk (ugly).
Or let depmod create a more easily parseable format on the disk (as Jakub suggested).
I don't think it's yet been proven that parsing the files is accounting for a significant portion of the time....
FWIW, I straced the parent udevd process during my F7 boot, and here's how it spent most of it's time:
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 67.93 0.157414 142 1105 288 waitpid 9.98 0.023130 4626 5 1 init_module 5.45 0.012638 2 6662 15 read 5.01 0.011601 48 240 execve ... ------ ----------- ----------- --------- --------- ---------------- 100.00 0.231726 58010 6125 total
-Eric
Ralf Ertzinger schrieb:
Hi.
On Tue, 11 Sep 2007 15:55:25 +0200, Harald Hoyer wrote:
modprobe is parsing its configuration/dependency files every time it is called.
What else should it do?
Kay and Greg thought about putting modprobe code in udev, so the config/dep files have to be read only once. Another idea was some kind of modprobe-daemon.
Harald Hoyer (harald@redhat.com) said:
12% (0.44s) with 60-net.rules
I am sure 60-net.rules does not have to call /etc/sysconfig/network-scripts/net.hotplug for _every_ "net" event.
What events are there besides add and remove? In any case, please file a bug and we'll get that fixed.
Bill
Harald Hoyer wrote:
Harald Hoyer schrieb:
44.1% (1,6s) with /sbin/modprobe
modprobe is parsing its configuration/dependency files every time it is called.
12% (0.44s) with 60-net.rules
I am sure 60-net.rules does not have to call /etc/sysconfig/network-scripts/net.hotplug for _every_ "net" event.
A while back I did some experiments with systemtap and found that modprobe was doing a linear search through modules.deps:
http://sourceware.org/ml/systemtap/2007-q1/msg00140.html
I wrote a script that would prepend the modules that are actually used to the beginning of modules.dep to reduce the average length of search. This reduced the amount of data read (and time spent waiting for I/O) and slightly reduced the time to boot the machine. Bootchart samples process state periodically. Below is some of the data extracted from the bootchart samples:
all states D state modprobe modprobe samples samples normal modules.dep 120 73 reordered modules.deps 63 27
Having to linearly through 250K of text in modules.dep each time a module is loaded doesn't seem very efficient.
-Will
William Cohen schrieb:
Harald Hoyer wrote:
Harald Hoyer schrieb:
44.1% (1,6s) with /sbin/modprobe
modprobe is parsing its configuration/dependency files every time it is called.
12% (0.44s) with 60-net.rules
I am sure 60-net.rules does not have to call /etc/sysconfig/network-scripts/net.hotplug for _every_ "net" event.
A while back I did some experiments with systemtap and found that modprobe was doing a linear search through modules.deps:
http://sourceware.org/ml/systemtap/2007-q1/msg00140.html
I wrote a script that would prepend the modules that are actually used to the beginning of modules.dep to reduce the average length of search. This reduced the amount of data read (and time spent waiting for I/O) and slightly reduced the time to boot the machine. Bootchart samples process state periodically. Below is some of the data extracted from the bootchart samples:
all states D state modprobe modprobe samples samples
normal modules.dep 120 73 reordered modules.deps 63 27
Having to linearly through 250K of text in modules.dep each time a module is loaded doesn't seem very efficient.
-Will
Problem is, that most of the modprobes with a modalias are not existent and so every line is parsed.
On Tue, Sep 11, 2007 at 05:40:27PM +0200, Harald Hoyer wrote:
A while back I did some experiments with systemtap and found that modprobe was doing a linear search through modules.deps:
http://sourceware.org/ml/systemtap/2007-q1/msg00140.html
I wrote a script that would prepend the modules that are actually used to the beginning of modules.dep to reduce the average length of search. This reduced the amount of data read (and time spent waiting for I/O) and slightly reduced the time to boot the machine. Bootchart samples process state periodically. Below is some of the data extracted from the bootchart samples:
all states D state modprobe modprobe samples samples
normal modules.dep 120 73 reordered modules.deps 63 27
Having to linearly through 250K of text in modules.dep each time a module is loaded doesn't seem very efficient.
-Will
Problem is, that most of the modprobes with a modalias are not existent and so every line is parsed.
If modules.dep searching really takes significant time, then there is always an option to precompile it into a more efficient format, e.g. more compact, with a hash table or whatever best matches modprobe's use.
Jakub
Harald Hoyer (harald@redhat.com) said:
For all of you who are bothered by the performance of udev:
I did some profiling, where udev spents its time... so here are the numbers:
Out of 3.63s of measured activity udev spent:
What rules were installed (out of all of the Fedora universe) - is this a base install?
Bill
Bill Nottingham schrieb:
Harald Hoyer (harald@redhat.com) said:
For all of you who are bothered by the performance of udev:
I did some profiling, where udev spents its time... so here are the numbers:
Out of 3.63s of measured activity udev spent:
What rules were installed (out of all of the Fedora universe) - is this a base install?
Bill
This was a F7 with latest udev-115. I will rerun this test with a rules-everything F8.
Harald Hoyer schrieb:
Bill Nottingham schrieb:
Harald Hoyer (harald@redhat.com) said:
For all of you who are bothered by the performance of udev:
I did some profiling, where udev spents its time... so here are the numbers:
Out of 3.63s of measured activity udev spent:
What rules were installed (out of all of the Fedora universe) - is this a base install?
Bill
This was a F7 with latest udev-115. I will rerun this test with a rules-everything F8.
Ok, did this with a rules-everything-rawhide on my laptop:
26 seconds
85% (22.3s) in modprobe 7.5% (2s) in 60-openct.rules:26 PROGRAM="/bin/sleep 0.1"
rest is below 0.5 seconds...
Eric Sandeen schrieb:
Harald Hoyer wrote:
Ok, did this with a rules-everything-rawhide on my laptop:
26 seconds
85% (22.3s) in modprobe 7.5% (2s) in 60-openct.rules:26 PROGRAM="/bin/sleep 0.1"
rest is below 0.5 seconds...
What exactly is the test you're running? Or did I miss that...
Thanks,
-Eric
my own version of udev with some ugly profiling code :-)
Harald Hoyer schrieb:
Ok, did this with a rules-everything-rawhide on my laptop:
26 seconds
85% (22.3s) in modprobe 7.5% (2s) in 60-openct.rules:26 PROGRAM="/bin/sleep 0.1"
rest is below 0.5 seconds...
Note: modprobe + kernel loading the modules is taking 22s Normally most of the modprobes are executed in parallel, so you normally don't have to wait 22s. Here for my test, I turned on sequential processing of the events. These are absolut times, including sleeps, e.g. for HW devices.
Bill Nottingham schrieb:
Harald Hoyer (harald@redhat.com) said:
Ok, did this with a rules-everything-rawhide on my laptop:
26 seconds
85% (22.3s) in modprobe
That doesn't make sense. Why does adding more rules make it call modprobe that much more?
Bill
Different system
Bill Nottingham schrieb:
Harald Hoyer (harald@redhat.com) said:
Ok, did this with a rules-everything-rawhide on my laptop:
26 seconds
85% (22.3s) in modprobe
That doesn't make sense. Why does adding more rules make it call modprobe that much more?
Bill
Doh.. had one firmware loading timeout due to the sequential profiling code. Here are the numbers without the timeout:
80-drivers.rules 2,922281 46,57% 95-pam-console.rules 1,130553 18,02% 60-net.rules 0,552256 8,80% 60-persistent-storage.rules 0,443388 7,07% 60-libsane.rules 0,307528 4,90% 90-alsa.rules 0,265658 4,23%
Using a modprobe wrapper, I count 56 /sbin/modprobe calls taking ~4s (non-profiling udev) on my laptop, from which 23 are not found. 23 * /sbin/modprobe with a modalias, which is not found, sums up to ~1s (25%) of the time. So we can easily eliminate 25% of the modprobe time (on my laptop), by collecting all /sys/***/modalias at depmod time, which cannot be resolved, and store them in /lib/modules/$(uname -r)/modules.unresolved, which could be searched first by modprobe.
On Wed, Sep 12, 2007 at 09:04:09AM +0200, Harald Hoyer wrote:
Using a modprobe wrapper, I count 56 /sbin/modprobe calls taking ~4s (non-profiling udev) on my laptop, from which 23 are not found. 23 * /sbin/modprobe with a modalias, which is not found, sums up to ~1s (25%) of the time. So we can easily eliminate 25% of the modprobe time (on my laptop), by collecting all /sys/***/modalias at depmod time, which cannot be resolved, and store them in /lib/modules/$(uname -r)/modules.unresolved, which could be searched first by modprobe.
BTW, each read_depends below will scan the whole modules.dep (if unsuccessful) or first part thereof. In the modprobes that take most of the time, is modules.dep read just once or multiple times?
/* Returns the resolved alias, options */ read_toplevel_config(config, modulearg, 0, remove, &modoptions, &commands, &aliases, &blacklist);
/* No luck? Try symbol names, if starts with symbol:. */ if (!aliases && strncmp(modulearg, "symbol:", strlen("symbol:")) == 0) read_config(symfilename, modulearg, 0, remove, &modoptions, &commands, &aliases, &blacklist);
if (!aliases) { /* We only use canned aliases as last resort. */ read_depends(dirname, modulearg, &list);
if (list_empty(&list) && !find_command(modulearg, commands)) { read_config(aliasfilename, modulearg, 0, remove, &modoptions, &commands, &aliases, &blacklist); aliases = apply_blacklist(aliases, blacklist); } }
if (aliases) { errfn_t err = error;
/* More than one alias? Don't bail out on failure. */ if (aliases->next) err = warn; while (aliases) { /* Add the options for this alias. */ char *opts = NOFAIL(strdup(optstring)); opts = add_extra_options(modulearg, opts, modoptions);
read_depends(dirname, aliases->module, &list); handle_module(aliases->module, &list, newname, remove, opts, first_time, err, dry_run, verbose, modoptions, commands, ignore_commands, ignore_proc, strip_vermagic, strip_modversion, unknown_silent, optstring);
aliases = aliases->next; INIT_LIST_HEAD(&list); } } else { if (use_blacklist && find_blacklist(modulearg, blacklist)) continue;
handle_module(modulearg, &list, newname, remove, optstring, first_time, error, dry_run, verbose, modoptions, commands, ignore_commands, ignore_proc, strip_vermagic, strip_modversion, unknown_silent, optstring); }
Jakub
Jakub Jelinek schrieb:
BTW, each read_depends below will scan the whole modules.dep (if unsuccessful) or first part thereof. In the modprobes that take most of the time, is modules.dep read just once or multiple times?
Hmm, don't know exactly what you mean... attached are the times.
modalias;real;user;sys
First modprobe takes the longest, as it fills the cache.
On Wed, Sep 12, 2007 at 09:29:45AM +0200, Harald Hoyer wrote:
Jakub Jelinek schrieb:
BTW, each read_depends below will scan the whole modules.dep (if unsuccessful) or first part thereof. In the modprobes that take most of the time, is modules.dep read just once or multiple times?
Hmm, don't know exactly what you mean... attached are the times.
modalias;real;user;sys
First modprobe takes the longest, as it fills the cache.
E.g. strace /sbin/modprobe pci:v0000104Cd0000803Bsv0000104Dsd000081EFbc01sc80i00 shows open("/lib/modules/2.6.22.1-27.fc7/modules.dep", O_RDONLY) = 3 + ~ 65 x 4KB read + parsing it in userspace open("/lib/modules/2.6.22.1-27.fc7/modules.alias", O_RDONLY) = 3 + ~ 65 x 4KB read + parsing it in userspace open("/lib/modules/2.6.22.1-27.fc7/modules.dep", O_RDONLY) = 3 + ~ 40 x 4KB read + parsing it in userspace
While both the big files are probably cached already, even the reads from cache and especially parsing can mean significant time spent in it.
I have ran 50 times /sbin/modprobe pci:v0000104Cd0000803Bsv0000104Dsd000081EFbc01sc80i00 under oprofile, 37.9% is spent in the kernel which I didn't have debuginfo for. But then we have: 0000003a628672a0 7031 24.6745 libc-2.6.so fgetc 0000000000402370 2974 10.4369 modprobe getline_wrapped 0000003a62877580 1299 4.5587 libc-2.6.so strpbrk 0000000000401310 871 3.0567 modprobe .plt 0000000000402d70 808 2.8356 modprobe underscores 0000003a628778c0 567 1.9898 libc-2.6.so strspn 0000003a62876a20 492 1.7266 libc-2.6.so strchr 0000003a6286e360 441 1.5476 libc-2.6.so malloc_consolidate 0000003a628705b0 396 1.3897 libc-2.6.so _int_malloc
static int fgetc_wrapped(FILE *file, unsigned int *linenum) { for (;;) { int ch = fgetc(file); if (ch != '\') return ch; ch = fgetc(file); if (ch != '\n') return ch; if (linenum) (*linenum)++; } }
static char *getline_wrapped(FILE *file, unsigned int *linenum) { int size = 1024; int i = 0; char *buf = NOFAIL(malloc(size)); for(;;) { int ch = fgetc_wrapped(file, linenum); if (i == size) { size *= 2; buf = NOFAIL(realloc(buf, size)); } if (ch < 0 && i == 0) { free(buf); return NULL; } if (ch < 0 || ch == '\n') { if (linenum) (*linenum)++; buf[i] = '\0'; return NOFAIL(realloc(buf, i+1)); } buf[i++] = ch; } }
Even just replacing fgetc with fgetc_unlocked should help tremendously, fgetc needs to lock the stream, so 2 atomic instructions per character plus it is a library call. fgetc_unlocked is inlined, needs no locking (modprobe isn't threaded, right?) and if there is anything buffered already (4095 out of 4096 times) it is just dereferencing a few pointers. The malloc/realloc/free per each line in the file (in my case 1486 malloc/frees times 2 for modules.dep and 5872 for modules.alias can be also avoided, from what I see all users of getline_wrapped always free what it returned and it is never called recursively. Which means there is no reason to malloc/free this every time. If instead this does: static int size = 0; static char *buf = NULL; ... if (i == size) { size = size ? size * 2 : 1024; buf = NOFAIL(realloc(buf, size)); } ... return buf; /* No second realloc. */ and never frees what getline_wrapped returned, you can always use the same buffer. Still, it is processing a significant amount of data, so while the above two proposed simple changes could give 10% or so, they won't kill the cost altogether. There are other inefficiencies all over, like: len = strlen(modname); if (strchr(modname, '.')) len = strchr(modname, '.') - modname; which gcc is at least ATM not able to optimize (while the duplicate strchr is called just once, gcc will call strlen unconditionally, even when it should be only called if strchr failed - though best is just use len = strchrnul(modname, '.') - modname; here.
With a prepared binary blob which would include a hash table for easy finding of dependencies for a module we could just open that, and only once. If the binary blob starts with a magic number and then has st_ino/st_dev/st_ctime of both modules.dep and modules.aliases in the same dir, then you can easily keep the text files for handediting purposes and only use the binary blob if the text files haven't changed since the binary blob was recreated, and let the depmod or whatever creates the binary files also create the binary blob and have a mode in which it creates the blob from the text files rather than from whatever it found on disk. modules.dep searches just for the basenames of modules without extension and dir component, and ignores differences between - and _. So, just create a hash function which handles - and _ the same and gives good results on the usual module names and stick a hash table (e.g. with chains) after the file header, then the chains would contain the actual module name's basename for module_equal comparison, full 32-bit hash and pointer to where the full strings are found in the string table (which should probably be compressed using a directory table). module.aliases is harder, because it contains wildcards, so hash table isn't useful, but some kind of tree, where each node would contain a length, sorted prefixes of that length plus leaf nodes that contain wildcards at that point already and thus need to be tested all by fnmatch. Searching would just in each node test all the wildcardish leaf nodes, if none matched binary search for what matches the prefix and recurse into that node. E.g. root node could have length of minimum of smallest alias name and smallest number of chars before first wildcard in any alias name (unless that is zero, otherwise the alias names starting with wildcard would go into the set needed to go through fnmatch at that level).
Jakub
Jakub Jelinek schrieb:
With a prepared binary blob which would include a hash table for easy finding of dependencies for a module we could just open that, and only once. If the binary blob starts with a magic number and then has st_ino/st_dev/st_ctime of both modules.dep and modules.aliases in the same dir, then you can easily keep the text files for handediting purposes and only use the binary blob if the text files haven't changed since the binary blob was recreated, and let the depmod or whatever creates the binary files also create the binary blob and have a mode in which it creates the blob from the text files rather than from whatever it found on disk. modules.dep searches just for the basenames of modules without extension and dir component, and ignores differences between - and _. So, just create a hash function which handles - and _ the same and gives good results on the usual module names and stick a hash table (e.g. with chains) after the file header, then the chains would contain the actual module name's basename for module_equal comparison, full 32-bit hash and pointer to where the full strings are found in the string table (which should probably be compressed using a directory table). module.aliases is harder, because it contains wildcards, so hash table isn't useful, but some kind of tree, where each node would contain a length, sorted prefixes of that length plus leaf nodes that contain wildcards at that point already and thus need to be tested all by fnmatch. Searching would just in each node test all the wildcardish leaf nodes, if none matched binary search for what matches the prefix and recurse into that node. E.g. root node could have length of minimum of smallest alias name and smallest number of chars before first wildcard in any alias name (unless that is zero, otherwise the alias names starting with wildcard would go into the set needed to go through fnmatch at that level).
Jakub
udev linked with libmodprobe.so, reading the config only once and having the above search tables in memory, would be the fastest solution.
On Wed, Sep 12, 2007 at 10:57:16AM +0200, Harald Hoyer wrote:
udev linked with libmodprobe.so, reading the config only once and having the above search tables in memory, would be the fastest solution.
No. If they are just read, rather than preparing hash table for modules.dep and search tree for modules.alias, then you just avoid the cost of reading it many times, but still spend the significant time parsing the data to find what you are looking for.
Jakub
Jakub Jelinek schrieb:
On Wed, Sep 12, 2007 at 10:57:16AM +0200, Harald Hoyer wrote:
udev linked with libmodprobe.so, reading the config only once and having the above search tables in memory, would be the fastest solution.
No. If they are just read, rather than preparing hash table for modules.dep and search tree for modules.alias, then you just avoid the cost of reading it many times, but still spend the significant time parsing the data to find what you are looking for.
Jakub
And that data parsing time can also be reduced by collecting the unresolvable modaliases at depmod time.
On Wed, 2007-09-12 at 11:18 +0200, Harald Hoyer wrote:
And that data parsing time can also be reduced by collecting the unresolvable modaliases at depmod time.
But given that hardware can and does change, I don't know that counting on this is really the best option. Especially when you think about things like live CDs, etc where the hardware you're running on is going to be vastly different than the hardware that depmod was run on
Jeremy
Jeremy Katz schrieb:
On Wed, 2007-09-12 at 11:18 +0200, Harald Hoyer wrote:
And that data parsing time can also be reduced by collecting the unresolvable modaliases at depmod time.
But given that hardware can and does change, I don't know that counting on this is really the best option. Especially when you think about things like live CDs, etc where the hardware you're running on is going to be vastly different than the hardware that depmod was run on
Jeremy
LiveCDs wouldn't benefit from it. True.
On Wed, 2007-09-12 at 11:18 +0200, Harald Hoyer wrote:
Jakub Jelinek schrieb:
On Wed, Sep 12, 2007 at 10:57:16AM +0200, Harald Hoyer wrote:
udev linked with libmodprobe.so, reading the config only once and having the above search tables in memory, would be the fastest solution.
No. If they are just read, rather than preparing hash table for modules.dep and search tree for modules.alias, then you just avoid the cost of reading it many times, but still spend the significant time parsing the data to find what you are looking for.
Jakub
And that data parsing time can also be reduced by collecting the unresolvable modaliases at depmod time.
Bloom filter?
Harald Hoyer schrieb:
For all of you who are bothered by the performance of udev:
I did some profiling, where udev spents its time... so here are the numbers:
Out of 3.63s of measured activity udev spent:
44.1% (1,6s) with /sbin/modprobe 13.3% (0,48s) with persistent-storage (mostly vol_id) 12% (0.44s) with 60-net.rules 10.5% (0.38s) with 90-alsa.rules 7% (0.25s) with pam_console (which will go away anyway)
Your numbers may vary because of different hardware.
*sigh*.. this is what I am talking about...
https://bugzilla.redhat.com/show_bug.cgi?id=291071
Summary: udev is too slow Product: Fedora Version: f8test2
Description: udev takes too long (>5 seconds) at boot.