Edit User (edit_user.cgi) needs to load several times before showing up properly

Hello,

on a virtual server of about 50 users, clicking on Edit Users and then trying to edit a specific user takes a few tries to actually load up in full, and until it does the page takes about 30 seconds to actually load, as if it's hitting a timeout. I'm attaching a screenshot of how it shows up initially, and how it is when loaded correctly on subsequent tries. It doesn't matter how many times I actually try to edit the user: even just trying again makes it load up correctly, as long as I give it enough time before trying again (usually 2-3 minutes). Once it's loaded correctly once, loading it again happens immediately for some time (haven't tested it, but could be hours).

It should be noted that the mailboxes are somewhat big; the machine is however high-end.

Status: 
Active

Comments

Howdy -- thanks for contacting us!

What browser/version are you using when this happens?

Also, if you use a different browser, do you see the same issue?

Hi,

the issue is happening with Chrome 73 and Firefox 64 on Debian 9, Ubuntu 18.04 and Windows 8.1/10. It has actually been happening for quite a long time, but I only got around reporting it now. I don't think it's a client-side issue.

If you SSH into the system and run top while the user page is loaded, does it show any process using up a lot of CPU?

A process named /usr/share/webmin/virtual-server/edit_user.cgi keeps running, even after the browser request timed out, so it's still doing something. When the process ends, a correct full page load can be achieved. It only takes 14-16 CPU% though (on a 8t Xeon E3-1275 v5).

If you SSH in as root and run strace -p followed by the PID of that edit_user.cgi process, what does it output?

strace reported a huge amount of stat activity, as follows (sensitive information omitted).

...
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518444143.14638_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=60787, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1526539439.32090_0.serverhost.com:2,RS", {st_mode=S_IFREG|0600, st_size=29466, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1526539439.32090_0.serverhost.com:2,RS", {st_mode=S_IFREG|0600, st_size=29466, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1526539439.32090_0.serverhost.com:2,RS", {st_mode=S_IFREG|0600, st_size=29466, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518452784.15053_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=86197, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518452784.15053_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=86197, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518452784.15053_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=86197, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518452461.10779_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=3714, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518452461.10779_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=3714, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518452461.10779_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=3714, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518453507.27733_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=1215209, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518453507.27733_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=1215209, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518453507.27733_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=1215209, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518518382.3384_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=60261, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518518382.3384_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=60261, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518518382.3384_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=60261, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518522367.24140_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=1275815, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518522367.24140_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=1275815, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518522367.24140_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=1275815, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518452277.7754_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=685593, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518452277.7754_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=685593, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518452277.7754_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=685593, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518453047.19624_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=75806, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518453047.19624_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=75806, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518453047.19624_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=75806, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518453348.24748_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=648167, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518453348.24748_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=648167, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518453348.24748_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=648167, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518428888.10586_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=487602, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518428888.10586_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=487602, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518428888.10586_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=487602, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518456392.6043_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=84051, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518456392.6043_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=84051, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518456392.6043_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=84051, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518428234.32658_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=67114, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518428234.32658_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=67114, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518428234.32658_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=67114, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518113760.29223_0.serverhost.com:2,RS", {st_mode=S_IFREG|0600, st_size=113572, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518113760.29223_0.serverhost.com:2,RS", {st_mode=S_IFREG|0600, st_size=113572, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518113760.29223_0.serverhost.com:2,RS", {st_mode=S_IFREG|0600, st_size=113572, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1527581964.11820_0.serverhost.com:2,", {st_mode=S_IFREG|0600, st_size=23112, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1527581964.11820_0.serverhost.com:2,", {st_mode=S_IFREG|0600, st_size=23112, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1527581964.11820_0.serverhost.com:2,", {st_mode=S_IFREG|0600, st_size=23112, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518453931.1860_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=717846, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518453931.1860_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=717846, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518453931.1860_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=717846, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518447795.5076_0.serverhost.com:2,RS", {st_mode=S_IFREG|0600, st_size=95880, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518447795.5076_0.serverhost.com:2,RS", {st_mode=S_IFREG|0600, st_size=95880, ...}) = 0
stat("/home/userdir/homes/username.userlname/Maildir/cur/1518447795.5076_0.serverhost.com:2,RS", {st_mode=S_IFREG|0600, st_size=95880, ...}) = 0
lstat("/home/userdir/homes/username.userlname/Maildir/cur/1518465626.10419_0.serverhost.com:2,S", {st_mode=S_IFREG|0600, st_size=2664, ...}) = 0
...

Out of curiosity, what is the output of this command:

ls /home/userdir/homes/username.userlname/Maildir/cur/ | wc -l

(note that you'll need to substitute the actual usernames above)

I'm wondering if maybe there's a particularly large amount of mail in that directory that's causing it to load slowly.

I tried with a very small mailbox (1.01 MB), it took about 20 seconds and cur has 3652 files. Other mailboxes' cur have more than 25000 files. However, fiddling around some more with strace, I noticed it also loops in folders' cur as well, not just the INBOX, so the more emails the mailbox has overall, the more it takes to edit the user.

What does it need to do this for? Can it be disabled?

Right now, there's no way to disable the function that counts up the size of the mailbox.

How long does it take to run find . in the same folder?

On the biggest mailboxes, executing find . in the respective homes takes 3 seconds peak on the first run.

What if you run find . -size +0

That actually takes considerably longer, I'd say on par with what experienced on Virtualmin.

Ok, so it looks like your filesystem is fairly slow to get the size of all those files.

The only solution I see would be to make display of the mailbox size optional for cases like this.

I'll try to tackle that with the filesystem devs. It's ocfs2, by the way. In the meanwhile, would there be any way to disable that?

Right now there's no way to disable the size display, as we assumed that it would normally be a fast operation.

I noticed find . takes normal time, whereas find . -size +0 is what takes significantly longer. That said, although probably not advisable, is there a way to make Virtualmin not check for size > 0 when listing the maildir in that scenario, even if it involves editing Perl source? Could you point me in the right direction? Thank you.

Looks like your filesystem is just slow at checking the size of files - Virtualmin needs to do this in order to count up the total size of the mailbox.

I'll add a config option in the next release to not show the mailbox size.

Thank you. Any potential release date for the release having such fix?