From mboxrd@z Thu Jan 1 00:00:00 1970 From: Kay Sievers Date: Mon, 04 Oct 2004 14:19:57 +0000 Subject: Re: Hanging udev process on nfs-mounted /dev Message-Id: <20041004141957.GA3086@vrfy.org> MIME-Version: 1 Content-Type: multipart/mixed; boundary="+QahgC5+KEYLbs62" List-Id: References: <415980BF.1020401@bio.ifi.lmu.de> In-Reply-To: <415980BF.1020401@bio.ifi.lmu.de> To: linux-hotplug@vger.kernel.org --+QahgC5+KEYLbs62 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline On Mon, Oct 04, 2004 at 08:15:46AM +0200, Frank Steiner wrote: > Kay Sievers wrote > > >Oh, bad. > >It's your running strace that prevents gbd to take the control over the > >process, I expect. Just try to send the strace parent-process a SIGUSR1 > >which may leave the udev process running. > > Yes, that worked :-) On one host there were already 3 udev processes > sharing all the CPU time, on the second it was just one. All four > traces look a little bit different, that's why I've attached all > four of them. I hope you can fetch sth. useful from the traces... Ok, let's look at it: > (gdb) bt > #0 0x400b91be in memcpy () from /lib/i686/libc.so.6 > #1 0x08056164 in tdb_read (tdb=0x80640a8, off=1073871052, buf=0xbffff2d8, > len=3221222108, cv=0) at tdb/tdb.c:407 > #2 0x080562b9 in ofs_read (tdb=0x4, offset=22728, d=0xbffff2d8) > at tdb/tdb.c:447 > #3 0x080567e4 in remove_from_freelist (tdb=0x80640a8, off=28176, next=696) > at tdb/tdb.c:628 > #4 0x080568d4 in tdb_free (tdb=0x80640a8, offset=27268, rec=0xbffff370) > at tdb/tdb.c:662 > #5 0x08056e2e in tdb_allocate (tdb=0x80640a8, length=884, rec=0xbffff3e0) > at tdb/tdb.c:910 > #6 0x08057e5a in tdb_store (tdb=0x80640a8, key= > {dptr = 0xbffff450 "/class/scsi_generic/sg3", dsize = 24}, dbuf= > {dptr = 0xbffff6a0 "sg3", dsize = 856}, flag=1) at tdb/tdb.c:1497 > #7 0x0804c361 in udevdb_add_dev (path=0xbfffff67 "/class/scsi_generic/sg3", > dev=0xbffff6a0) at udevdb.c:76 > #8 0x0804bb66 in udev_add_device (path=0xbfffff67 "/class/scsi_generic/sg3", > subsystem=0xbfffff45 "scsi_generic", fake=0) at udev-add.c:446 > #9 0x0804971f in main (argc=2, argv=0xbffffd70, envp=0x4) at udev.c:185 This seems to be a loop in tdb_allocate(). > (gdb) bt > #0 tdb_oob (tdb=0x80640a8, len=3221222944, probe=7004) at tdb/tdb.c:342 > #1 0x0805638b in rec_read (tdb=0x80640a8, offset=7004, rec=0xbffff620) > at tdb/tdb.c:466 > #2 0x0805703e in tdb_find (tdb=0x80640a8, key= > {dptr = 0xbfffff60 "/class/scsi_device/26:0:0:0", dsize = 28}, hash=536231552, > r=0xbffff620) at tdb/tdb.c:990 > #3 0x080571b8 in tdb_find_lock (tdb=0x80640a8, key= > {dptr = 0xbfffff60 "/class/scsi_device/26:0:0:0", dsize = 28}, locktype=0, > rec=0xbffff620) at tdb/tdb.c:1035 > #4 0x080572ef in tdb_fetch (tdb=0x80640a8, key= > {dptr = 0xbfffff60 "/class/scsi_device/26:0:0:0", dsize = 28}) at tdb/tdb.c:1113 > #5 0x0804c3a3 in udevdb_get_dev (path=0xffffff00
, > dev=0xbffff6a0) at udevdb.c:89 > #6 0x0804c17f in udev_remove_device (path=0xbfffff60 "/class/scsi_device/26:0:0:0", > subsystem=0xbfffff45 "block") at udev-remove.c:170 > #7 0x08049760 in main (argc=2, argv=0xbffffd70, envp=0x1b74) at udev.c:189 This is the loop in tdb_find(). > (gdb) bt > #0 0x08055f9a in tdb_oob (tdb=0x80640a8, len=7028, probe=0) at tdb/tdb.c:344 > #1 0x0805613c in tdb_read (tdb=0x80640a8, off=7004, buf=0xbffff620, len=24, cv=0) > at tdb/tdb.c:403 > #2 0x0805631e in rec_read (tdb=0x80640a8, offset=7004, rec=0xbffff620) > at tdb/tdb.c:458 > #3 0x0805703e in tdb_find (tdb=0x80640a8, key= > {dptr = 0xbfffff61 "/class/scsi_device/9:0:0:2", dsize = 27}, hash=3221149257, > r=0xbffff620) at tdb/tdb.c:990 > #4 0x080571b8 in tdb_find_lock (tdb=0x80640a8, key= > {dptr = 0xbfffff61 "/class/scsi_device/9:0:0:2", dsize = 27}, locktype=0, > rec=0xbffff620) at tdb/tdb.c:1035 > #5 0x080572ef in tdb_fetch (tdb=0x80640a8, key= > {dptr = 0xbfffff61 "/class/scsi_device/9:0:0:2", dsize = 27}) at tdb/tdb.c:1113 > #6 0x0804c3a3 in udevdb_get_dev (path=0x0, dev=0xbffff6a0) at udevdb.c:89 > #7 0x0804c17f in udev_remove_device (path=0xbfffff61 "/class/scsi_device/9:0:0:2", > subsystem=0xbfffff46 "block") at udev-remove.c:170 > #8 0x08049760 in main (argc=2, argv=0xbffffd70, envp=0x0) at udev.c:189 The same tdb_find() loop. > (gdb) bt > #0 ofs_read (tdb=0xbffff438, offset=20016, d=0x0) at tdb/tdb.c:446 > #1 0x080567e4 in remove_from_freelist (tdb=0x80640a8, off=20016, next=0) > at tdb/tdb.c:628 > #2 0x080568d4 in tdb_free (tdb=0x80640a8, offset=19108, rec=0xbffff520) > at tdb/tdb.c:662 > #3 0x08057586 in do_delete (tdb=0x80640a8, rec_ptr=19108, rec=0xbffff520) > at tdb/tdb.c:1215 > #4 0x08057cc4 in tdb_delete (tdb=0x80640a8, key= > {dptr = 0xbffff570 "/class/scsi_generic/sg2", dsize = 24}) at tdb/tdb.c:1434 > #5 0x0804c475 in udevdb_delete_dev (path=0xbfffff64 "/class/scsi_generic/sg2") > at udevdb.c:112 > #6 0x0804c218 in udev_remove_device (path=0xbfffff64 "/class/scsi_generic/sg2", > subsystem=0xbfffff42 "scsi_generic") at udev-remove.c:182 > #7 0x08049760 in main (argc=2, argv=0xbffffd70, envp=0xbffff438) at udev.c:189 Seems to be a loop in remove_from_freelist(). All here known failure paths are now covered in the attached patch by limiting the iteration count for loops over data read from disk. Let's see what happens next :) Kay --+QahgC5+KEYLbs62 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline; filename="udev-deadlock-debug-03.patch" ===== namedev.c 1.146 vs edited ===== --- 1.146/namedev.c 2004-09-08 15:17:55 +02:00 +++ edited/namedev.c 2004-10-04 15:24:31 +02:00 @@ -29,7 +29,6 @@ #include #include #include -#include #include #include #include @@ -353,7 +352,6 @@ static struct bus_file { {} }; -#define SECONDS_TO_WAIT_FOR_FILE 10 static void wait_for_device_to_initialize(struct sysfs_device *sysfs_device) { /* sleep until we see the file for this specific bus type show up this @@ -367,14 +365,14 @@ static void wait_for_device_to_initializ struct bus_file *b = &bus_files[0]; struct sysfs_attribute *tmpattr; int found = 0; - int loop = SECONDS_TO_WAIT_FOR_FILE; + int loop = WAIT_FOR_FILE_SECONDS * WAIT_FOR_FILE_RETRY_FREQ; while (1) { if (b->bus == NULL) { if (!found) break; - /* sleep to give the kernel a chance to create the file */ - sleep(1); + /* give the kernel a chance to create the file */ + usleep(1000 * 1000 / WAIT_FOR_FILE_RETRY_FREQ); --loop; if (loop == 0) break; @@ -394,7 +392,8 @@ static void wait_for_device_to_initializ } if (!found) dbg("did not find bus type '%s' on list of bus_id_files, " - "contact greg@kroah.com", sysfs_device->bus); + "please report to ", + sysfs_device->bus); exit: return; /* here to prevent compiler warning... */ } @@ -682,7 +681,6 @@ static struct sysfs_device *get_sysfs_de { struct sysfs_device *sysfs_device; struct sysfs_class_device *class_dev_parent; - struct timespec tspec; int loop; /* Figure out where the device symlink is at. For char devices this will @@ -698,16 +696,14 @@ static struct sysfs_device *get_sysfs_de if (class_dev_parent != NULL) dbg("given class device has a parent, use this instead"); - tspec.tv_sec = 0; - tspec.tv_nsec = 10000000; /* sleep 10 millisec */ - loop = 10; + loop = WAIT_FOR_FILE_SECONDS * WAIT_FOR_FILE_RETRY_FREQ; while (loop--) { if (udev_sleep) { if (whitelist_search(class_dev)) { sysfs_device = NULL; goto exit; } - nanosleep(&tspec, NULL); + usleep(1000 * 1000 / WAIT_FOR_FILE_RETRY_FREQ); } if (class_dev_parent) @@ -729,11 +725,9 @@ device_found: if (sysfs_device->bus[0] != '\0') goto bus_found; - loop = 10; - tspec.tv_nsec = 10000000; while (loop--) { if (udev_sleep) - nanosleep(&tspec, NULL); + usleep(1000 * 1000 / WAIT_FOR_FILE_RETRY_FREQ); sysfs_get_device_bus(sysfs_device); if (sysfs_device->bus[0] != '\0') ===== udev-add.c 1.73 vs edited ===== --- 1.73/udev-add.c 2004-08-05 00:41:08 +02:00 +++ edited/udev-add.c 2004-10-04 15:24:31 +02:00 @@ -340,11 +340,10 @@ exit: /* wait for the "dev" file to show up in the directory in sysfs. * If it doesn't happen in about 10 seconds, give up. */ -#define SECONDS_TO_WAIT_FOR_FILE 10 static int sleep_for_file(const char *path, char* file) { char filename[SYSFS_PATH_MAX + 6]; - int loop = SECONDS_TO_WAIT_FOR_FILE; + int loop = WAIT_FOR_FILE_SECONDS * WAIT_FOR_FILE_RETRY_FREQ; int retval; strfieldcpy(filename, sysfs_path); @@ -360,7 +359,7 @@ static int sleep_for_file(const char *pa goto exit; /* sleep to give the kernel a chance to create the dev file */ - sleep(1); + usleep(1000 * 1000 / WAIT_FOR_FILE_RETRY_FREQ); } retval = -ENODEV; exit: ===== udev.c 1.62 vs edited ===== --- 1.62/udev.c 2004-09-14 02:25:32 +02:00 +++ edited/udev.c 2004-10-04 15:24:31 +02:00 @@ -36,6 +36,9 @@ #include "namedev.h" #include "udevdb.h" +/* timeout flag for udevdb */ +extern sig_atomic_t gotalarm; + /* global variables */ char **main_argv; char **main_envp; @@ -58,6 +61,11 @@ void log_message(int level, const char * asmlinkage static void sig_handler(int signum) { switch (signum) { + case SIGALRM: + gotalarm = 1; + info("error: timeout reached, event probably not handled correctly, " + "please report to "); + break; case SIGINT: case SIGTERM: udevdb_exit(); @@ -94,7 +102,8 @@ int main(int argc, char *argv[], char *e dbg("version %s", UDEV_VERSION); - /* initialize our configuration */ + init_logging("udev"); + udev_init_config(); if (strstr(argv[0], "udevstart")) { @@ -147,15 +156,20 @@ int main(int argc, char *argv[], char *e /* set signal handlers */ act.sa_handler = sig_handler; sigemptyset (&act.sa_mask); + + /* alarm should interrupt */ + sigaction(SIGALRM, &act, NULL); + act.sa_flags = SA_RESTART; sigaction(SIGINT, &act, NULL); sigaction(SIGTERM, &act, NULL); + /* trigger timout to interrupt blocking syscalls */ + alarm(ALARM_TIMEOUT); + /* initialize udev database */ - if (udevdb_init(UDEVDB_DEFAULT) != 0) { - dbg("unable to initialize database"); - goto exit; - } + if (udevdb_init(UDEVDB_DEFAULT) != 0) + info("error: unable to initialize database, continuing without database"); switch(act_type) { case UDEVSTART: ===== udev.h 1.62 vs edited ===== --- 1.62/udev.h 2004-09-14 14:29:10 +02:00 +++ edited/udev.h 2004-10-04 15:24:31 +02:00 @@ -26,6 +26,9 @@ #include #include "libsysfs/sysfs/libsysfs.h" +#define ALARM_TIMEOUT 20 +#define WAIT_FOR_FILE_SECONDS 10 +#define WAIT_FOR_FILE_RETRY_FREQ 10 #define COMMENT_CHARACTER '#' #define NAME_SIZE 256 ===== udevdb.c 1.30 vs edited ===== --- 1.30/udevdb.c 2004-06-29 14:51:35 +02:00 +++ edited/udevdb.c 2004-10-04 15:24:31 +02:00 @@ -42,13 +42,28 @@ #include "tdb/tdb.h" static TDB_CONTEXT *udevdb; +sig_atomic_t gotalarm; +static void tdb_log(TDB_CONTEXT *tdb, int level, const char *format, ...) +{ + va_list args; + + if (!udev_log) + return; + + va_start(args, format); + vsyslog(level, format, args); + va_end(args); +} int udevdb_add_dev(const char *path, const struct udevice *dev) { TDB_DATA key, data; char keystr[SYSFS_PATH_MAX]; + if (udevdb == NULL) + return -1; + if ((path == NULL) || (dev == NULL)) return -ENODEV; @@ -68,6 +83,9 @@ int udevdb_get_dev(const char *path, str { TDB_DATA key, data; + if (udevdb == NULL) + return -1; + if (path == NULL) return -ENODEV; @@ -88,6 +106,9 @@ int udevdb_delete_dev(const char *path) TDB_DATA key; char keystr[SYSFS_PATH_MAX]; + if (udevdb == NULL) + return -1; + if (path == NULL) return -EINVAL; @@ -121,7 +142,9 @@ int udevdb_init(int init_flag) if (init_flag != UDEVDB_DEFAULT && init_flag != UDEVDB_INTERNAL) return -EINVAL; - udevdb = tdb_open(udev_db_filename, 0, init_flag, O_RDWR | O_CREAT, 0644); + tdb_set_lock_alarm(&gotalarm); + + udevdb = tdb_open_ex(udev_db_filename, 0, init_flag, O_RDWR | O_CREAT, 0644, tdb_log); if (udevdb == NULL) { if (init_flag == UDEVDB_INTERNAL) dbg("unable to initialize in-memory database"); @@ -137,7 +160,7 @@ int udevdb_init(int init_flag) */ int udevdb_open_ro(void) { - udevdb = tdb_open(udev_db_filename, 0, 0, O_RDONLY, 0); + udevdb = tdb_open_ex(udev_db_filename, 0, 0, O_RDONLY, 0, tdb_log); if (udevdb == NULL) { dbg("unable to open database at '%s'", udev_db_filename); return -EACCES; @@ -159,6 +182,9 @@ static int traverse_callback(TDB_CONTEXT int udevdb_call_foreach(int (*user_record_handler) (char *path, struct udevice *dev)) { int retval = 0; + + if (udevdb == NULL) + return -1; if (user_record_handler == NULL) { dbg("invalid user record handling function"); ===== tdb/tdb.c 1.3 vs edited ===== --- 1.3/tdb/tdb.c 2003-12-17 01:23:27 +01:00 +++ edited/tdb/tdb.c 2004-10-04 16:01:26 +02:00 @@ -616,8 +616,10 @@ int tdb_printfreelist(TDB_CONTEXT *tdb) static int remove_from_freelist(TDB_CONTEXT *tdb, tdb_off off, tdb_off next) { tdb_off last_ptr, i; + int maxloop; /* read in the freelist top */ + maxloop = 100000; last_ptr = FREELIST_TOP; while (ofs_read(tdb, last_ptr, &i) != -1 && i != 0) { if (i == off) { @@ -626,6 +628,12 @@ static int remove_from_freelist(TDB_CONT } /* Follow chain (next offset is at start of record) */ last_ptr = i; + + maxloop--; + if (maxloop == 0) { + TDB_LOG((tdb, 0, "remove_from_freelist: maxloop reached; corrupt database!\n")); + return TDB_ERRCODE(TDB_ERR_CORRUPT, -1); + } } TDB_LOG((tdb, 0,"remove_from_freelist: not on list at off=%d\n", off)); return TDB_ERRCODE(TDB_ERR_CORRUPT, -1); @@ -852,6 +860,7 @@ static tdb_off tdb_allocate(TDB_CONTEXT { tdb_off rec_ptr, last_ptr, newrec_ptr; struct list_struct newrec; + int maxloop; if (tdb_lock(tdb, -1, F_WRLCK) == -1) return 0; @@ -867,6 +876,7 @@ static tdb_off tdb_allocate(TDB_CONTEXT goto fail; /* keep looking until we find a freelist record big enough */ + maxloop = 100000; while (rec_ptr) { if (rec_free_read(tdb, rec_ptr, rec) == -1) goto fail; @@ -918,6 +928,12 @@ static tdb_off tdb_allocate(TDB_CONTEXT /* move to the next record */ last_ptr = rec_ptr; rec_ptr = rec->next; + + maxloop--; + if (maxloop == 0) { + TDB_LOG((tdb, 0, "tdb_allocate: maxloop reached; corrupt database!\n")); + return TDB_ERRCODE(TDB_ERR_CORRUPT, 0); + } } /* we didn't find enough space. See if we can expand the database and if we can then try again */ @@ -980,12 +996,14 @@ static tdb_off tdb_find(TDB_CONTEXT *tdb struct list_struct *r) { tdb_off rec_ptr; - + int maxloop; + /* read in the hash top */ if (ofs_read(tdb, TDB_HASH_TOP(hash), &rec_ptr) == -1) return 0; /* keep looking until we find the right record */ + maxloop = 100000; while (rec_ptr) { if (rec_read(tdb, rec_ptr, r) == -1) return 0; @@ -1005,6 +1023,12 @@ static tdb_off tdb_find(TDB_CONTEXT *tdb SAFE_FREE(k); } rec_ptr = r->next; + + maxloop--; + if (maxloop == 0) { + TDB_LOG((tdb, 0, "tdb_find maxloop reached; corrupt database!\n")); + return TDB_ERRCODE(TDB_ERR_CORRUPT, 0); + } } return TDB_ERRCODE(TDB_ERR_NOEXIST, 0); } @@ -1187,6 +1211,7 @@ static int do_delete(TDB_CONTEXT *tdb, t { tdb_off last_ptr, i; struct list_struct lastrec; + int maxloop; if (tdb->read_only) return -1; @@ -1201,9 +1226,18 @@ static int do_delete(TDB_CONTEXT *tdb, t /* find previous record in hash chain */ if (ofs_read(tdb, TDB_HASH_TOP(rec->full_hash), &i) == -1) return -1; - for (last_ptr = 0; i != rec_ptr; last_ptr = i, i = lastrec.next) + + maxloop = 100000; + for (last_ptr = 0; i != rec_ptr; last_ptr = i, i = lastrec.next) { if (rec_read(tdb, i, &lastrec) == -1) return -1; + + maxloop--; + if (maxloop == 0) { + TDB_LOG((tdb, 0, "(tdb)do_delete: maxloop reached; corrupt database!\n")); + return TDB_ERRCODE(TDB_ERR_CORRUPT, -1); + } + } /* unlink it: next ptr is at start of record. */ if (last_ptr == 0) --+QahgC5+KEYLbs62-- ------------------------------------------------------- This SF.net email is sponsored by: IT Product Guide on ITManagersJournal Use IT products in your business? Tell us what you think of them. Give us Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more http://productguide.itmanagersjournal.com/guidepromo.tmpl _______________________________________________ Linux-hotplug-devel mailing list http://linux-hotplug.sourceforge.net Linux-hotplug-devel@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/linux-hotplug-devel