last day (16 days later) » 

21:56
0
Q: One particular uid causes very slow dd performance

John JiangOne of our accounts on a centos 7 machine experienced very slow disk read/write. id uid=1007(test.dd) gid=1001(xxx) groups=1001(xxx),10(wheel) ulimit -m 100000000; sudo dd if=/dev/zero of=/tmp/test1.img bs=1G count=1 oflag=dsync [sudo] password for test.dd: 1+0 records in 1+0 records out 1073741...

This has to be an issue with your testing methodology. There's nothing that would make a specific user slower. Did you make sure you dropped the page cache before tests?
@forest Thanks. I just tried and succeeded with " sudo sh -c ' echo 3 > /proc/sys/vm/drop_caches ' ", but still got ulimit -m 100000000; dd if=/dev/zero of=/tmp/test1.img bs=1G count=1 oflag=dsync 1+0 records in 1+0 records out 1073741824 bytes (1.1 GB) copied, 27.1012 s, 39.6 MB/s
Is /tmp mounted as tmpfs?
@forest df -h indeed reveals the following mount point "tmpfs 26G 0 26G 0% /run/user/1007". I will umount it and try again. Meanwhile could you shed some light on why it can slow disk down? Thanks!
Well if it was running as tmpfs then you know that it's not the disk itself that is slow. Also doing bs=1G is highly inefficient. The block size is usually best at around 256k or so. Btw, you did sudo dd which means that both commands are running as euid 0.
21:56
@forest Indeed there was also a "tmpfs /run/user/0" entry under "df -h". I removed both, and ran dd command without sudo, but still got about 40 MB/s under the account with uid 1007. I started looking into this because the 1007 user on this machine ran wget much slower than other user/machines.
Just replaced /tmp/test1.img with dev/test1.img and got similar speed: 45MB/sec. Maybe need to replace /dev/zero with something else but not sure how.
22:06
@JohnJiang Try replacing /tmp/whatever with /dev/null.
That way you're narrowing down the benchmark to just i/o, not page cache.
@JohnJiang Try running a shell as root, and use sudo -u whateveruser.
_ something about the /dev mount point is treating user 1007 and other users differently._ I don't think that's possible. It'd have to be something else.
@forest indeed I have been using /dev/null since half an hour ago. The results remain unchanged. I also noticed that with /dev/zero replaced by /dev/urandom, the 4x gap disappears. With bs=1M the gap also disappears, but not with large bs like 1G, 2G. Somehow 1007 is configured differently but don't know where to look.
22:21
Unless you're also doing things like applying configurations for that user, then 1007 should be no different from any other UID. You could try writing a very simple C program that uses setuid().
Then you can use UIDs even if they don't have corresponding entries in /etc/passwd.
#include <unistd.h>
#include <stdlib.h>

int main(int argc, char *argv[])
{
	int id = (argc > 1) ? atoi(argv[1]) : 0;

	if (setgid(id) < 0 || setuid(id) < 0)
		return 1;

	system("dd if=/dev/zero of=/dev/null bs=256k count=4096");
	return 0;
}
@JohnJiang Try something like that. Run as root. Takes one argument: a UID.
I can write a more advanced test if you want.
22:53
@forest thanks a lot! I tried a variant of your c code, and indeed setuid to 1007 didn't matter. So it's only the user that's logged in that causes the speed gap.
#include <stdio.h>
#include <unistd.h>

int main(int argc, char** argv) {
printf( "%d\n", setuid(atoi(argv[1]) ));
printf( "%d\n", getuid());
const FILE *fd = popen("ulimit -m 100000000; dd if=/dev/zero of=/tmp/test1.img bs=1G count=1 oflag=dsync","w");
pclose(fd);
}
id: uid=1008(yyy) gid=1001(xxx) groups=1001(xxx),10(wheel),994(docker)
sudo ./a.out 1007
0
1007
1+0 records in
1+0 records out
1073741824 bytes (1.1 GB) copied, 6.28947 s, 171 MB/s
id
uid=1007(test.dd) gid=1001(xxx) groups=1001(xxx),10(wheel)
So whatever the problem is must have to do with some settings for that user.
sudo ./a.out 1008
0
1008
1+0 records in
1+0 records out
1073741824 bytes (1.1 GB) copied, 26.4992 s, 40.5 MB/s
Are you sure it's only 1007?
What are your ulimits?
yes, 1007 is actually my personal uid. Other people's account had no disk speed issue.
ulimit returns unlimited under both 1007 and 1008.
Also I recently ran userdel -r and groupdel on the old user for 1007, so things like .bashrc, .bash_profile should have been removed already.
Are any disk quotas set up?
And do you get the same perf hit when writing from /dev/zero to /dev/null?
23:02
No disk quota I am aware of. Yes, /dev/zero -> /dev/null sees the same 4x perf gap as /dev/zero -> /tmp/test1.img
Try to find out if it's specifically about I/O, or if performance in general is lower.
Create a busy while loop and see how fast it is.
OK good idea.
Something like: timeout 10 bash -c 'i=0; while :; do i=$(($i+1)); done; echo $i'
Well, not that exactly since it won't print.
But something like that.
This should work: time bash -c 'for i in {0..1000000}; do :; done'
#include <stdio.h>
#include <unistd.h>
#include <time.h>
int main(int argc, char** argv) {
clock_t before = clock();
int i;
for (i = 0; i < 1e9; ++i) {
int x = 12345 * 12345;
}
clock_t difference = clock() - before;
int msec = difference * 1000 / CLOCKS_PER_SEC;

printf("Time taken %d seconds %d milliseconds (%d iterations)\n",
msec/1000, msec%1000, 1e9);
}
this printed similar results on 1007 and 1008: Time taken 2 seconds 590 milliseconds (590 iterations)
You can press the "fixed font" button before sending and then it'll be formatted nice. :P
23:09
your command also returned similar results
ah, ok thx
time bash -c 'for i in {0..1000000}; do :; done'

real	0m2.110s
user	0m1.978s
sys	0m0.132s
Huh, so it genuinely seems to be limited to I/O. Try using a read() and write() loop instead of system().
Btw I think int x = 12345 * 12345 is likely to be optimized out by the compiler. But it doesn't matter.
#include <fcntl.h>
#include <unistd.h>

#define BUFSZ 262144

void main(void)
{
	char buf[BUFSZ];

	int fd1 = open("/dev/zero", O_RDONLY);
	int fd2 = open("/dev/null", O_WRONLY);

	for (int i = 0; i < 100000; i++) {
		read(fd1, buf, BUFSZ);
		write(fd2, buf, BUFSZ);
	}
}
Can easily test it with shell builtin time, no need to use clock().
ok, I tried something in bash first
uid=1008 ; time bash -c "for i in {0..1} ; do cat test1.img > /tmp/test2.img ; done "

real	0m6.865s
user	0m0.008s
sys	0m2.016s
uid=1007 ; time bash -c "for i in {0..1} ; do cat test1.img > /tmp/test2.img ; done "

real	0m13.123s
user	0m0.004s
sys	0m2.609s
deleted the target file before hand in both cases.
Does strace show that the cat syscalls are identical?
your code returned similar time results
Try testing if it's both reading and writing that is having issues, or just one or the other.
#include <fcntl.h>
#include <unistd.h>

#define BUFSZ 262144

int main(void)
{
	char buf[BUFSZ];
	int fd = open("/dev/zero", O_RDONLY);

	for (int i = 0; i < 100000; i++) {
		read(fd,  buf, BUFSZ);
	}

	return 0;
}
#include <fcntl.h>
#include <unistd.h>

#define BUFSZ 262144

int main(void)
{
	char buf[BUFSZ] = { 0 };
	int fd = open("/dev/null", O_WRONLY);

	for (int i = 0; i < 100000; i++) {
		write(fd,  buf, BUFSZ);
	}

	return 0;
}
23:23
strace returned some diff, but I don't know it well enough to know the meaning:
1,3c1,3
< execve("/usr/bin/cat", ["cat", "test1.img"], [/* 22 vars */]) = 0
< brk(NULL)                               = 0x2345000
< mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2a61d40000
---
> execve("/usr/bin/cat", ["cat", "test1.img"], [/* 28 vars */]) = 0
> brk(NULL)                               = 0x1708000
> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f637975d000
7c7
< mmap(NULL, 62854, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f2a61d30000
let me try your read/write separate c code
though with them combined, there was little perf difference.
Read as uid 1007 and read as uid 1008 are the same speed?
your read c code returned
uid=1007:
real 0m1.669s
user 0m0.007s
sys 0m1.631s

uid=1008:
real 0m1.690s
user 0m0.003s
sys 0m1.687s
You can also use strace -Tt which will provide timing information for the syscalls. That'll at least allow you to tell if it's the syscalls themselves that are slow (meaning it's something in userspace telling the kernel to slow down, as opposed to some e.g. environmental variable causing userspace code to do something inefficient).
So that means that read speed isn't affected, only write, perhaps?
write for loop:
uid=1007:
real	0m0.025s
user	0m0.005s
sys	0m0.020s

uid=1008:
real	0m0.025s
user	0m0.003s
sys	0m0.022s
Must've done something wrong. That seems like the program exited immediately.
23:27
ok let me double check
Or maybe I didn't put in enough iterations.
add two more zeros to the for loop upper bound, and ran time ./a.out got longer time:

uid=1007:
real	0m1.141s
user	0m0.209s
sys	0m0.932s

uid=1008:
real	0m1.095s
user	0m0.199s
sys	0m0.896s
Add three more zeros maybe, to see if this is just noise or if write() is actually slower between 1007 and 1008.
Also, what environmental variables do you have in whatever user is 1007 and 1008?
(command is env)
with 3 zeros:

uid=1007:
real	0m16.416s
user	0m0.069s
sys	0m16.346s

uid=1008:
real	0m15.398s
user	0m0.075s
sys	0m15.322s
That seems insignificant.
This is odd. It seems like, between 1007 and 1008 dd is slower, and read()+write() is slower, but read() alone is not slower, and write() is not appreciably slower.
23:33
diff env.1007 env.1008
1c1
< XDG_SESSION_ID=33604
---
> XDG_SESSION_ID=33651
6,8c6,11
< SSH_CLIENT=100.124.208.22 53035 22
< SSH_TTY=/dev/pts/2
< USER=yunjiang.jiang
---
> SSH_CLIENT=100.124.208.22 63884 22
> CONDA_SHLVL=1
> CONDA_PROMPT_MODIFIER=
> OLDPWD=/home
> SSH_TTY=/dev/pts/0
> USER=search
9a13
> CONDA_EXE=/home/search/anaconda3/bin/conda
11,12c15,17
< MAIL=/var/spool/mail/yunjiang.jiang
< PATH=/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/usr/Arcconf:/home/yunjiang.jiang/.local/bin:/home/yunjiang.jiang/bin
@forest thats' true. I think the read/write speed is only affected when block size is large.
Try using a larger block size then. What's odd is that a large block size just means that there's more overhead copying data between kernelspace and userspace, but the filesystem and disk driver overhead are the same. I can't think of anything that would cause memory copying speed to go down because of some difference between users. Is there anything else that is different between users? The environment is similar enough, you said the ulimit -a was the same...
One thing I do in this sort of scenario is trying to minimize all the uncounted for variables by doing the tests in single user mode, so I can guarantee there are no daemons, etc.
I have created a completely new user with an unused uid, and it worked just fine, with fast dd speed.
make sense. the setuid was a good idea. But it looks like it's the actual log-in that made the difference.
Yeah it's certainly something being done upon login.
But it doesn't look like something in environ. All I can think of is some policy slowing things down. Perhaps something like auditd enabled for that user, which causes some syscalls to run slower.
Hence the suggestion to try it in single user mode.
23:57
I killed one auditd process. There is another one under root that I can't kill -9. The original results remain unchanged.
the one killed:
root       1087  0.0  0.0  55464  1104 ?        S<sl Apr25   0:09 /sbin/auditd
If you can't kill -9 then I'm guessing it's init.

  last day (16 days later) »