seq_file: Use larger buffer to reduce time traversing lists
I've just been taking a look at the seq_read() code, since we've noticed that dumping files with large numbers of records can take some considerable time. This is due to seq_read() using a buffer which, at most is a single page in size, and that it has to find its place again on every call to seq_read(). That makes it rather inefficient.
As an example, I created a GFS2 filesystem with 100k inodes in it, and then ran ls -l to get a decent number of cached inodes. This result in there being approx 400k lines in the debugfs file containing GFS2's glocks. I then timed how long it takes to read this file:
[root at chywoon mnt]# time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=1M
0+5769 records in
0+5769 records out
23273958 bytes (23 MB) copied, 63.3681 s, 367 kB/s
real 1m3.371s user 0m0.005s sys 1m3.317s
I tried this several times and it seems pretty consistent. Then I tried again with the below patch applied:
[root at chywoon mnt]# time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=1M
0+23 records in
0+23 records out
23107575 bytes (23 MB) copied, 1.64175 s, 14.1 MB/s
real 0m1.644s
user 0m0.000s
sys 0m1.643s
So that is a speed up of approx 38x, which isn't too bad I think. I noticed that currently, the code caches the buffer page rather than doing a free/alloc on each seq_read() call. Since my patch can make that buffer rather large, I was not sure that this was a good idea, in general, as it would seem to lead to potential DoS attacks in pinning down large amounts of kmalloced memory. So my patch will free the buffer on each cycle unless it is only a single page in size. That way we won't pin down any more memory than the current code does, even when using a larger buffer. I suspect that any time spent doing alloc/free will be more than made up by the reduction in time traversing the records in the file.
Also, since multipage kmalloc allocations are likely to fail in low memory conditions, I've made that happen silently, and it falls back to a single page buffer if a larger buffer cannot be allocated.
fs/seq_file.c +17 -0
@@ -153,7 +153,9 @@ ssize_t seq_read(struct file *file, char __user *buf, size_t size, loff_t *ppos)size_t n;void *p;int err =0 ; +unsigned bsize =clamp (size,PAGE_SIZE ,KMALLOC_MAX_SIZE ); + bsize =round_up (bsize,PAGE_SIZE );mutex_lock (&m->lock);/*
@@ -169,6 +171,16 @@ ssize_t seq_read(struct file *file, char __user *buf, size_t size, loff_t *ppos)*/ m->version = file->f_version; +if ((m->size < bsize) || !m->buf) { +kfree (m->buf); + m->size =0 ; + m->buf =kmalloc (m->size = bsize,GFP_KERNEL |__GFP_NOWARN); +if (!m->buf) + m->buf =kmalloc (m->size =PAGE_SIZE ,GFP_KERNEL ); +if (!m->buf) + goto Enomem; + } +/* Don't assume *ppos is where we left it */ if (unlikely (*ppos != m->read_pos)) {while ((err =traverse (m, *ppos)) == -EAGAIN )
@@ -277,6 +289,11 @@ Done: m->read_pos += copied; } file->f_version = m->version; +if (m->size >PAGE_SIZE ) { +kfree (m->buf); + m->buf =NULL ; + m->size =0 ; + }mutex_unlock (&m->lock);return copied; Enomem:
Quoted 11 lines · Steven Whitehouse
I've just been taking a look at the
seq_read()code, since we've noticed that dumping files with large numbers of records can take some considerable time. This is due toseq_read()using a buffer which, at most is a single page in size, and that it has to find its place again on every call toseq_read(). That makes it rather inefficient.As an example, I created a GFS2 filesystem with 100k inodes in it, and then ran ls -l to get a decent number of cached inodes. This result in there being approx 400k lines in the debugfs file containing GFS2's glocks. I then timed how long it takes to read this file:
Quoted 5 lines
[root@chywoon mnt]# time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=1M
0+5769 records in
0+5769 records out
23273958 bytes (23 MB) copied, 63.3681 s, 367 kB/s
What time do you get if you do
time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=4k
This patch seems the wrong way to me.
seq_read(size = 1MB) should perform many copy_to_user() calls instead of a single one.
Instead of doing kmalloc(m->size <<= 1, GFP_KERNEL) each time we overflow the buffer, we should flush its content to user space.
Quoted 20 lines · Eric Dumazet
Quoted 11 lines · Steven Whitehouse
I've just been taking a look at the
seq_read()code, since we've noticed that dumping files with large numbers of records can take some considerable time. This is due toseq_read()using a buffer which, at most is a single page in size, and that it has to find its place again on every call toseq_read(). That makes it rather inefficient.As an example, I created a GFS2 filesystem with 100k inodes in it, and then ran ls -l to get a decent number of cached inodes. This result in there being approx 400k lines in the debugfs file containing GFS2's glocks. I then timed how long it takes to read this file:
Quoted 5 lines
[root@chywoon mnt]# time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=1M
0+5769 records in
0+5769 records out
23273958 bytes (23 MB) copied, 63.3681 s, 367 kB/sWhat time do you get if you do
Quoted 10 lines
time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=4k
This patch seems the wrong way to me.
seq_read(size = 1MB)should perform manycopy_to_user()calls instead of a single one.Instead of doing
kmalloc(m->size <<= 1, GFP_KERNEL)each time we overflow the buffer, we should flush its content to user space.
by the way, is the following command even working ?
time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=16M
I guess not, it probably returns -ENOMEM
Hi,
Quoted 32 lines · Eric Dumazet
Quoted 20 lines · Eric Dumazet
Quoted 11 lines · Steven Whitehouse
I've just been taking a look at the
seq_read()code, since we've noticed that dumping files with large numbers of records can take some considerable time. This is due toseq_read()using a buffer which, at most is a single page in size, and that it has to find its place again on every call toseq_read(). That makes it rather inefficient.As an example, I created a GFS2 filesystem with 100k inodes in it, and then ran ls -l to get a decent number of cached inodes. This result in there being approx 400k lines in the debugfs file containing GFS2's glocks. I then timed how long it takes to read this file:
Quoted 5 lines
[root at chywoon mnt]# time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=1M
0+5769 records in
0+5769 records out
23273958 bytes (23 MB) copied, 63.3681 s, 367 kB/sWhat time do you get if you do
Quoted 10 lines
time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=4k
This patch seems the wrong way to me.
seq_read(size = 1MB)should perform manycopy_to_user()calls instead of a single one.Instead of doing
kmalloc(m->size <<= 1, GFP_KERNEL)each time we overflow the buffer, we should flush its content to user space.
Quoted 8 lines
by the way, is the following command even working ?
time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=16M
I guess not, it probably returns
-ENOMEM
Why would it return -ENOMEM? It works for me, at worst it will fall back to a single page buffer size unless we are really stuck for memory, and in that case, all bets are off,
Steve.
Hi,
Quoted 18 lines · Eric Dumazet
Quoted 11 lines · Steven Whitehouse
I've just been taking a look at the
seq_read()code, since we've noticed that dumping files with large numbers of records can take some considerable time. This is due toseq_read()using a buffer which, at most is a single page in size, and that it has to find its place again on every call toseq_read(). That makes it rather inefficient.As an example, I created a GFS2 filesystem with 100k inodes in it, and then ran ls -l to get a decent number of cached inodes. This result in there being approx 400k lines in the debugfs file containing GFS2's glocks. I then timed how long it takes to read this file:
Quoted 5 lines
[root at chywoon mnt]# time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=1M
0+5769 records in
0+5769 records out
23273958 bytes (23 MB) copied, 63.3681 s, 367 kB/s
Quoted 4 lines
What time do you get if you do
time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=4k
Yes, you are right that it will be slow, still. But I'm not sure what we can do about that. We have to find our place again on each read call, in any case I think.
Quoted 9 lines
This patch seems the wrong way to me.
seq_read(size = 1MB)should perform manycopy_to_user()calls instead of a single one.Instead of doing
kmalloc(m->size <<= 1, GFP_KERNEL)each time we overflow the buffer, we should flush its content to user space.
Yes, I thought of that... there is a potential problem though. Is it valid to do a copy to user while between ->seq_start() and ->seq_stop() in general? These might be holding locks which may potentially be required during a page fault caused by the copy_to_user(). Thats not an issue in the GFS2 case, but I don't know if it is generally ok to do that. I assume that is why the results are buffered rather than being directly written to userspace anyway.
As soon as we do a ->seq_stop, then we have to go through the whole list (assuming a list based data source) again to find our place :(
Steve.
Quoted 3 lines · Steven Whitehouse
Yes, you are right that it will be slow, still. But I'm not sure what we can do about that. We have to find our place again on each read call, in any case I think.
You dont really answer my question, I asked the exact timing...
I can't reproduce this slow behavior you have, using /proc/net seq files.
Isn't it a problem with this particular file ?
Does it want to output a single record ( m->op->show(m, p) ) much larger than 4KB ?
Hi,
Quoted 8 lines · Eric Dumazet
Quoted 3 lines · Steven Whitehouse
Yes, you are right that it will be slow, still. But I'm not sure what we can do about that. We have to find our place again on each read call, in any case I think.
You dont really answer my question, I asked the exact timing...
Here it is (with the patch):
[root at chywoon mnt]# time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=4k
0+5726 records in
0+5726 records out
23107575 bytes (23 MB) copied, 82.3082 s, 281 kB/s
real 1m22.311s
user 0m0.013s
sys 1m22.231s
So thats slow, as promised :-)
Quoted 5 lines
I can't reproduce this slow behavior you have, using
/proc/netseq files.Isn't it a problem with this particular file ?
Well, yes and no. The problem would affect any file with lots of records in it, but there may not be many with that number of records. Do any of your net files have numbers of entries in the region of hundreds of thousands or more?
Quoted 3 lines
Does it want to output a single record (
m->op->show(m, p)) much larger than 4KB ?
No. That appears to work ok, so far as I can tell, anyway. What we have are lots of relatively short records. Here is an example of a few lines. Each line starting G: is a new record, so this is 5 calls to ->show():
G: s:SH n:5/1da5e f:Iqob t:SH d:EX/0 a:0 v:0 r:2 m:200
H: s:SH f:EH e:0 p:6577 [(ended)] gfs2_inode_lookup+0x116/0x2d0 [gfs2]
G: s:SH n:2/a852 f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:9712/43090 t:8 f:0x00 d:0x00000000 s:0
G: s:SH n:2/8bcd f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:2584/35789 t:8 f:0x00 d:0x00000000 s:0
G: s:SH n:2/1eea7 f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:58968/126631 t:8 f:0x00 d:0x00000000 s:0
G: s:SH n:2/12fbd f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:11120/77757 t:8 f:0x00 d:0x00000000 s:0
The key here is that we have a lot of them. My example using just over 400k records is in fact a fairly modest example - it is not unusual to see millions of records in this file. We use it for debug purposes only, and this patch was prompted by people reporting it taking a very long time to dump the file.
The issue is not the time taken to create each record, or to copy the data, but the time taken each time we have to find our place again in the list of glocks (actually a hash table, but same thing applies as we traverse it as a set of lists)
I don't think there is really much we can easily do in the case of readers requesting small reads of the file. At least we can make it much more efficient when they request larger reads though,
Steve.
Quoted 49 lines · Steven Whitehouse
Here it is (with the patch):
[root@chywoon mnt]# time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=4k
0+5726 records in
0+5726 records out
23107575 bytes (23 MB) copied, 82.3082 s, 281 kB/sreal 1m22.311s
user 0m0.013s
sys 1m22.231sSo thats slow, as promised :-)
Quoted 5 lines
I can't reproduce this slow behavior you have, using
/proc/netseq files.Isn't it a problem with this particular file ?
Well, yes and no. The problem would affect any file with lots of records in it, but there may not be many with that number of records. Do any of your net files have numbers of entries in the region of hundreds of thousands or more?
Quoted 3 lines
Does it want to output a single record (
m->op->show(m, p)) much larger than 4KB ?No. That appears to work ok, so far as I can tell, anyway. What we have are lots of relatively short records. Here is an example of a few lines. Each line starting G: is a new record, so this is 5 calls to ->show():
G: s:SH n:5/1da5e f:Iqob t:SH d:EX/0 a:0 v:0 r:2 m:200
H: s:SH f:EH e:0 p:6577 [(ended)]gfs2_inode_lookup+0x116/0x2d0[gfs2]
G: s:SH n:2/a852 f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:9712/43090 t:8 f:0x00 d:0x00000000 s:0
G: s:SH n:2/8bcd f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:2584/35789 t:8 f:0x00 d:0x00000000 s:0
G: s:SH n:2/1eea7 f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:58968/126631 t:8 f:0x00 d:0x00000000 s:0
G: s:SH n:2/12fbd f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:11120/77757 t:8 f:0x00 d:0x00000000 s:0The key here is that we have a lot of them. My example using just over 400k records is in fact a fairly modest example - it is not unusual to see millions of records in this file. We use it for debug purposes only, and this patch was prompted by people reporting it taking a very long time to dump the file.
Quoted 8 lines
The issue is not the time taken to create each record, or to copy the data, but the time taken each time we have to find our place again in the list of glocks (actually a hash table, but same thing applies as we traverse it as a set of lists)
I don't think there is really much we can easily do in the case of readers requesting small reads of the file. At least we can make it much more efficient when they request larger reads though,
Issue is your seq_file provider has O(N^2) behavior
We used to have same issues in network land, and we fixed this some time ago, and we only use 4KB as seq_file buffer, not a huge one.
Check commit a8b690f98baf9fb1 ( tcp: Fix slowness in read /proc/net/tcp ) for an example
Hi,
Quoted 56 lines · Eric Dumazet
Quoted 54 lines · Steven Whitehouse
Here it is (with the patch):
[root at chywoon mnt]# time dd if=/sys/kernel/debug/gfs2/unity\:myfs/glocks of=/dev/null bs=4k
0+5726 records in
0+5726 records out
23107575 bytes (23 MB) copied, 82.3082 s, 281 kB/sreal 1m22.311s
user 0m0.013s
sys 1m22.231sSo thats slow, as promised :-)
Quoted 5 lines
I can't reproduce this slow behavior you have, using
/proc/netseq files.Isn't it a problem with this particular file ?
Well, yes and no. The problem would affect any file with lots of records in it, but there may not be many with that number of records. Do any of your net files have numbers of entries in the region of hundreds of thousands or more?
Quoted 3 lines
Does it want to output a single record (
m->op->show(m, p)) much larger than 4KB ?No. That appears to work ok, so far as I can tell, anyway. What we have are lots of relatively short records. Here is an example of a few lines. Each line starting G: is a new record, so this is 5 calls to ->show():
G: s:SH n:5/1da5e f:Iqob t:SH d:EX/0 a:0 v:0 r:2 m:200
H: s:SH f:EH e:0 p:6577 [(ended)]gfs2_inode_lookup+0x116/0x2d0[gfs2]
G: s:SH n:2/a852 f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:9712/43090 t:8 f:0x00 d:0x00000000 s:0
G: s:SH n:2/8bcd f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:2584/35789 t:8 f:0x00 d:0x00000000 s:0
G: s:SH n:2/1eea7 f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:58968/126631 t:8 f:0x00 d:0x00000000 s:0
G: s:SH n:2/12fbd f:IqLob t:SH d:EX/0 a:0 v:0 r:2 m:200
I: n:11120/77757 t:8 f:0x00 d:0x00000000 s:0The key here is that we have a lot of them. My example using just over 400k records is in fact a fairly modest example - it is not unusual to see millions of records in this file. We use it for debug purposes only, and this patch was prompted by people reporting it taking a very long time to dump the file.
The issue is not the time taken to create each record, or to copy the data, but the time taken each time we have to find our place again in the list of glocks (actually a hash table, but same thing applies as we traverse it as a set of lists)
Quoted 6 lines
Quoted 3 lines
I don't think there is really much we can easily do in the case of readers requesting small reads of the file. At least we can make it much more efficient when they request larger reads though,
Issue is your
seq_fileprovider has O(N^2) behavior
Well that is a slight simplification. The provider has O(N) behaviour wrt to the number of entries when streaming data, and O(N) behaviour when seeking to a specific file offset. It is the combination of repeated calls of the seeking function that results in O(N^2)
Quoted 6 lines
We used to have same issues in network land, and we fixed this some time ago, and we only use 4KB as
seq_filebuffer, not a huge one.Check commit
a8b690f98baf9fb1( tcp: Fix slowness in read/proc/net/tcp) for an example
So far as I can tell, you are just caching the last hash bucket, but are still seeking down each hash chain. That will only work well when the hash buckets are reasonably empty. We can try that in GFS2, however I'm not sure that is the whole story.
It appears that /proc/net/unix still seems to suffer from this O(N^2) problem, even if /proc/net/tcp does not. I did a quick test using a program to create a bunch of tcp sockets, and using my kernel patch landed up with these results:
[root at chywoon mnt]# time dd if=/proc/net/tcp of=/dev/null bs=4k 0+1046 records in
0+1046 records out
4236300 bytes (4.2 MB) copied, 1.20739 s, 3.5 MB/s
real 0m1.310s
user 0m0.003s
sys 0m1.220s
[root at chywoon mnt]# time dd if=/proc/net/tcp of=/dev/null bs=1M 0+5 records in
0+5 records out
4236300 bytes (4.2 MB) copied, 0.331139 s, 12.8 MB/s
real 0m0.470s
user 0m0.001s
sys 0m0.374s
So even with the current tcp scheme this appears to speed things up by nearly 3x. Also that was with only 28000 entries in the file,
Steve.
Quoted 4 lines · Steven Whitehouse
0m0.374sSo even with the current tcp scheme this appears to speed things up by nearly 3x. Also that was with only 28000 entries in the file,
Initial speedup was 100x, not 3x.
Of course using a 32KB buffer instead of 4KB will help.
And If someones need 100.000 active unix sockets and fast /proc/net/udp file as well, patch is welcome. If I have time I can do it eventually.
Really, kmalloc(2 MB) is not going to happen, even using __GFP_NOWARN
Quoted 1 line · Eric Dumazet
And If someones need 100.000 active unix sockets and fast
/proc/net/udp
I meant /proc/net/unix here, of course...
Quoted 2 lines
file as well, patch is welcome. If I have time I can do it eventually.
All unix sockets are linked into a single list, no hash table, so its not very easy right now.
Quoted 3 lines · Eric Dumazet
All unix sockets are linked into a single list, no hash table, so its not very easy right now.
Oops, there is a hash table, so patch is coming ;)
Hi,
Quoted 9 lines · Eric Dumazet
Quoted 3 lines · Eric Dumazet
All unix sockets are linked into a single list, no hash table, so its not very easy right now.
Oops, there is a hash table, so patch is coming ;)
The only reason that I looked at the unix sockets was that Nate Straz, who originally reported the issue to me had sent me a test program for unix sockets which he wrote in response to one of your earlier emails. So I converted it to tcp just to do that quick test,
Steve.
Hi,
Quoted 8 lines · Eric Dumazet
Quoted 4 lines · Steven Whitehouse
0m0.374sSo even with the current tcp scheme this appears to speed things up by nearly 3x. Also that was with only 28000 entries in the file,
Initial speedup was 100x, not 3x.
According to the patch description, that 100x was with 182k entries. That is not comparing like with like, although I accept that that did provide a really good improvement. I'm not suggesting that we should have one approach or the other, but that both are worth considering. I'll certainly have a look at the hash table based approach too.
Quoted 7 lines
Of course using a 32KB buffer instead of 4KB will help.
And If someones need 100.000 active unix sockets and fast
/proc/net/udpfile as well, patch is welcome. If I have time I can do it eventually.Really, kmalloc(2 MB) is not going to happen, even using
__GFP_NOWARN
It is designed so that if this allocation fails, then we just fall back to the old slow way, so I'm not sure that this is an issue. It will not fail to work just because the initial kmalloc fails, so we would be no worse off than with the current code, and we could also trim down the top size limit to something a bit smaller than KMALLOC_MAX_SIZE and still get most of the benefit. I just chose that as a convenient upper limit to show the principle.
Also, I think it wouldn't be unreasonable to argue that if the probability of a KMALLOC_MAX_SIZE allocation failing is so high that it is very unlikely to ever succeed, then perhaps KMALLOC_MAX_SIZE is too large.
So I know that I might have not convinced you :-) but I still think that perhaps something along these lines is worth considering. I had looked at various other possible ways of achieving a similar effect but all of those I rejected in the end, as they fell foul of some of the subtleties of the seq_read() code,
Steve.
Quoted 1 line · Steven Whitehouse
I'll certainly have a look at the hash table based approach too.
This is the reasonable approach, because most seq_file users do :
cat /path | ...
FILE *F = fopen("/path", "r");
ie they use small read size (<= 32 KB)
NOWARN can still slow down the whole machine.
You apparently don't have machines with fragmented memory...
hint : __GFP_NORETRY & PAGE_ALLOC_COSTLY_ORDER
Quoted 1 line · Steven Whitehouse
I've just been taking a look at the
seq_read()code,
[]
nice improvement. trivial style comment:
fs/seq_file.c
Quoted 1 line
fs/seq_file.c +0
-0
[]
fs/seq_file.c ssize_t seq_read(struct file *file, char __user *buf, size_t size, loff_t *ppos) · line 177
Quoted 8 lines
fs/seq_file.c +4
-0@@ -169,6 +171,16 @@ ssize_t seq_read(struct file *file, char __user *buf, size_t size, loff_t *ppos)*/ m->version = file->f_version; +if ((m->size < bsize) || !m->buf) { +kfree (m->buf); + m->size =0 ; + m->buf =kmalloc (m->size = bsize,GFP_KERNEL |__GFP_NOWARN);
You can remove the m->size = 0 line and can you please add a space around the |? It's a bit dense and too easy to read it as a single word.
fs/seq_file.c ssize_t seq_read(struct file *file, char __user *buf, size_t size, loff_t *ppos) · line 181
Quoted 4 lines
fs/seq_file.c +4
-0+if (!m->buf) + m->buf =kmalloc (m->size =PAGE_SIZE ,GFP_KERNEL ); +if (!m->buf) + goto Enomem;
Mixed case label?
fs/seq_file.c Done: · line 299
Quoted 12 lines
fs/seq_file.c +5
-0@@ -277,6 +289,11 @@ Done: m->read_pos += copied; } file->f_version = m->version; +if (m->size >PAGE_SIZE ) { +kfree (m->buf); + m->buf =NULL ; + m->size =0 ; + }mutex_unlock (&m->lock);return copied; Enomem:
Oh, it wasn't you. nevermind...