Hello > I think the log is reliable basically, and the lacking of timestamp is > not a problem becuase the aufs debug messages print it. > The line > aufs au_dbg_cond:74:mount[11763]: DEBUG: 0, 1798.258628 means > "cpu id", "elapsed time since boot" > > We can see > aufs au_dbg_cond:74:mount[11774]: DEBUG: 1, 1799.554563 at the > first 14:49:57 log. > Also by grep + cut + uniq -c the log, I got > ::: > 32 1798 > 41 1799 > 1 1800 > 1 nd[11775]: DEBUG: 8 <-- this line is simply broken due to > syslog-ng. > 28 1800 > 90 1801 > 90 1802 > ::: > which means that aufs processed 32 inodes in one second, 1798 - 1799. > And in the next one second (1799 - 1800) aufs processed 41 inodes. > These numbers of the processed inodes are relative low, which means > aufs works slow. During 1739 - 1796, aufs processed about 50 inodes per > second. > And in the next one second (1800 - 1801) aufs processed about 30 inodes > again. > Interestingly, after 1801, aufs processed about 90 inodes per second. > > From your log, the maximum aufs performance on your system looks about > 90 inodes per second, and when the system becomes busy it gets about 3 > times lower (or worse). > > > > If the mount command is hanging I see this messages: > ::: > > 2012-01-26 14:50:15 chgut12fw01 kernel: aufs > > au_dbg_cond:74:mount[11774]: DEBUG: 1, 1817.347161 > > But aufs and the mount process did not seems to be hang totally. It was > still working and just became slow, wasn't it? (I know "too slow" is > nearly equal to "hang")
You are right. I think most of the time, the command is not really hanging. Normally the remount-duration is ~30 seconds. But I had some cases, where the duration was much more. A few minutes up to some hours. I think there is a point, after which the command really hangs. > > Could it be a problem with the kernel thread "fsnotify_mark"? > > Maybe. > But, *currently* I don't think it is a problem of fsnotify. > We saw the fsnotify_mark kthread stopped at synchronize_srcu() in > fsnotify_mark_destroy(), and it was waiting for the completion of > another task. Currently, I trust fsnotify and srcu, and don't find any > problem (which may cause your problem) in them. > > Assuming your "mount" process did NOT hang actually and it just happen > a simple slow-down, I think it is caused by VFS and aufs, just my > current guess. > - Generally VFS caches dentry (filename) and inode when it is accessed. > - When remounting, VFS tries discarding all unused (but cached) > dentryies and inodes. > When you run "find" and "remount" at the same time, these caching and > uncaching operations run concurrently. By "find", the dentries are > cached more and more. By remount, VFS tries discarding them, all of > them. But it won't end easily because the "find" producer is still > running. Of course, the "find" producer will end eventualy, but it may > take long time. > > In your scenario, you have three processes (threads) for two CPUs > (right?) > - mount > VFS tries discarding the all cached-unused inode, which makes aufs > and > fsnotiy to free the "notify" trick by passing the data to the > fsnotify_mark kthread. > - find > it digs the directory tree, and aufs sets the "notify" trick to them. > - fsnotify_mark kthread > it waits for the data to free. > > The context-switch among them might become very heavy. This is my > current guess. You are right. I have two CPU's. I have some news: The problem happens only on multi-CPU systems. I have a Virtualbox System. When I configure only 1 CPU, everything is normal. If I change to 2 CPU's, The remount duration is much longer. How can it be, that a simple read can slow down the remount? A option like "noatime" doesn't change anything. "coo" is set to "none". Is there another option which I can try? See my test results below. > On the other hand, there is a method (d_delete) to stop VFS caching the > unused dentries. Some filesystems implement it, but others don't. Aufs > doesn't implement it either. > If aufs implemented the method, the number of unused-but-cached > dentries would be 0 and the VFS remount operation will not wait. > Let's try this method. > Here is a patch for it. It still may take long time, but will become > much shorter I hope. Anfortunately this patch doesn't change the duration. :-( My test is now a little bit simpler: # mount / -o remount,udba=notify; find /usr -type f &>/dev/null; time mount / -o remount,udba=reval And here the results: Virtualbox Host with 1 CPU: real 0m0.023s user 0m0.000s sys 0m0.017s Same Virtualbox Host with 2 CPUs: real 0m42.252s user 0m0.000s sys 0m0.113s Same Virtualbox Host with 2 CPUs and option "noatime" specified: # mount / -o remount,udba=notify,noatime; find /usr -type f &>/dev/null; time mount / -o remount,udba=reval,noatime real 0m37.930s user 0m0.000s sys 0m0.120s Same Virtualbox Host with 2 CPUs and "find /" instead of "find /usr": real 4m39.627s user 0m0.000s sys 0m0.740s Here the problem host with your aufs-patch applied (and "find /usr"): real 0m31.378s user 0m0.000s sys 0m0.043s And here the problem host with 2 CPUs and our old Kernel 2.6.35: real 0m0.031s user 0m0.000s sys 0m0.023s AUFS Version was: 2-standalone.tree-35-20100823 Any idea, what else I can do? Best regards Elmar
smime.p7s
Description: S/MIME cryptographic signature
------------------------------------------------------------------------------ Try before you buy = See our experts in action! The most comprehensive online learning library for Microsoft developers is just $99.99! Visual Studio, SharePoint, SQL - plus HTML5, CSS3, MVC3, Metro Style Apps, more. Free future releases when you subscribe now! http://p.sf.net/sfu/learndevnow-dev2
