madvise system call with MADV_SEQIENTIAL option taking too long to finish

a52362@trbvm.com · 08-06-2014, 06:13 AM

While using an external close-source library in my code I came across with a problem related to madvice() system call with MADV_SEQUENTIAL option. My code blocks for 5 minutes while using this external library. When I trace my code using strace I saw that when my code calls close-source library madvice() with MADV_SEQUENTIAL is called in the library which takes too long to finish(takes about 2-5 minutes). Do you have any idea why this could happen? My machine's memory status is also given as debug info. Also what is the purpose of calling madvice() more than once?

Code:

[root@dev ~]# strace application
...
open("/usr/local/largefile", O_RDONLY) = 9
fstat64(9, {st_mode=S_IFREG|0644, st_size=952270848, ...}) = 0
mmap2(NULL, 1073741824, PROT_READ, MAP_SHARED, 9, 0) = 0x78280000
madvise(0x78280000, 1073741824, MADV_NORMAL) = 0
madvise(0x78280000, 1073741824, MADV_RANDOM) = 0    
madvise(0x78280000, 1073741824, MADV_SEQUENTIAL) = 0

...

Code is run on 32 bit linux kernel v3.4.52.

Code:

[root@dev ~]# free -lk
             total       used       free     shared    buffers     cached
Mem:       4034412    3419344     615068          0      55712     767824
Low:        853572     495436     358136
High:      3180840    2923908     256932
-/+ buffers/cache:    2595808    1438604
Swap:      4192960     218624    3974336

Code:

[root@dev ~]# cat /proc/buddyinfo 
Node 0, zone      DMA     89     23      9      4      5      4      4      1      0      2      0 
Node 0, zone   Normal   9615   7099   3997   1723    931    397     78      0      0      1      1 
Node 0, zone  HighMem   7313   8089   2187    420    206     92     41     15      8      3      6

NevemTeve · 08-06-2014, 07:07 AM

Note: Use strace with -tt option to get timestamps.

a52362@trbvm.com · 08-08-2014, 12:42 AM

This time it took only 24 seconds but sometimes it takes more.

Code:

08:39:20.136922 open("/usr/local/largefile", O_RDONLY) = 8
08:39:20.136957 fstat64(8, {st_mode=S_IFREG|0644, st_size=952664064, ...}) = 0
08:39:20.137011 mmap2(NULL, 1073741824, PROT_READ, MAP_SHARED, 8, 0) = 0x7754c000
08:39:20.137040 madvise(0x7754c000, 1073741824, MADV_NORMAL) = 0
08:39:20.137070 madvise(0x7754c000, 1073741824, MADV_RANDOM) = 0
08:39:20.137928 madvise(0x7754c000, 1073741824, MADV_SEQUENTIAL) = 0
08:39:44.019819 madvise(0x7754c000, 1073741824, MADV_RANDOM) = 0

NevemTeve · 08-08-2014, 02:42 AM

It might be the program itself that run between 08:39:20 and 08:39:44... Sow now try

Code:

strace -tt -T executable

a52362@trbvm.com · 08-11-2014, 05:43 AM

It seems that madvise does not take the time. Do you have any idea about the wait between madvise(..,MADV_SEQUENTIAL) and madvise(..,MADV_RANDOM).

Code:

13:11:35.358982 open("/usr/local/largefile", O_RDONLY) = 8 <0.000010>
13:11:35.359060 fstat64(8, {st_mode=S_IFREG|0644, st_size=953360384, ...}) = 0 <0.000006>
13:11:35.359155 mmap2(NULL, 1073741824, PROT_READ, MAP_SHARED, 8, 0) = 0x7755e000 <0.000007>
13:11:35.359223 madvise(0x7755e000, 1073741824, MADV_NORMAL) = 0 <0.000006>
13:11:35.359266 madvise(0x7755e000, 1073741824, MADV_RANDOM) = 0 <0.000006>
13:11:35.359886 madvise(0x7755e000, 1073741824, MADV_SEQUENTIAL) = 0 <0.000006>
13:11:53.730549 madvise(0x7755e000, 1073741824, MADV_RANDOM) = 0 <0.000013>

NevemTeve · 08-11-2014, 06:34 AM

It's the programmers how could tell you. They might process the whole file between the two 'madvise',