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

Submitted by markkuit on Fri, 04/19/2019 - 04:00

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
Files: 
Image icon first.png
Image icon subsequent.png

Comments

Submitted by andreychek on Fri, 04/19/2019 - 08:32

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?

Submitted by markkuit on Fri, 04/19/2019 - 08:53

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.

Submitted by JamieCameron on Sat, 04/20/2019 - 14:25

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?

Submitted by markkuit on Tue, 04/23/2019 - 03:00

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).

Submitted by JamieCameron on Sat, 04/27/2019 - 19:33

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

Submitted by markkuit on Thu, 05/02/2019 - 07:24

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
...

Submitted by andreychek on Thu, 05/02/2019 - 10:11

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.

Submitted by markkuit on Tue, 05/07/2019 - 10:00

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?

Submitted by JamieCameron on Wed, 05/08/2019 - 22:50

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?

Submitted by markkuit on Fri, 05/10/2019 - 08:01

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

Submitted by JamieCameron on Sun, 05/12/2019 - 14:43

What if you run find . -size +0

Submitted by markkuit on Sun, 05/12/2019 - 14:58

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

Submitted by JamieCameron on Sun, 05/12/2019 - 15:24

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

Submitted by JamieCameron on Sun, 05/12/2019 - 15:28

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

Submitted by markkuit on Fri, 05/17/2019 - 04:09

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?

Submitted by JamieCameron on Sat, 05/18/2019 - 14:21

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

Submitted by markkuit on Tue, 06/11/2019 - 04:53

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.

Submitted by JamieCameron on Mon, 06/24/2019 - 00:15

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.

Submitted by JamieCameron on Mon, 06/24/2019 - 00:37

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

Submitted by markkuit on Mon, 07/01/2019 - 04:13

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