[Bug 551] New: tail performance is very bad

[bugzilla at busybox.net]

https://bugs.busybox.net/show_bug.cgi?id=551

              Host: i386
            Target: i386
           Summary: tail performance is very bad
           Product: Busybox
           Version: 1.14.x
          Platform: PC
        OS/Version: Linux
            Status: NEW
          Severity: enhancement
          Priority: P5
         Component: Other
        AssignedTo: unassigned at busybox.net
        ReportedBy: denys at visp.net.lb
                CC: busybox-cvs at busybox.net
   Estimated Hours: 0.0


Hi

I notice huge difference in tail of busybox comparing with util-linux busybox.
tail -f, for example, from util-linux on increasing large log (around 5GB) with
busybox, it takes around one minute just to show up last lines.

Probably it is possible to change something in algorithm?

Here is strace comparison for interesting parts

util-linux
open("/var/log/messages", O_RDONLY)     = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=13752879, ...}) = 0
lseek(3, 0, SEEK_CUR)                   = 0
lseek(3, 0, SEEK_END)                   = 13752879
lseek(3, 13746176, SEEK_SET)            = 13746176
read(3, "ast -9, max_rtt 582\nAug  8 17:09:56 sunfire-1 distnetmond: <insatgx>
12 max jitter, last -9, max_rtt 582\nAug  8 17:09:56 sunfire-1 distnetmond:
<greeks> 12 max jitter
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 10), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7fcb91347000
write(1, "Aug  8 17:10:10 sunfire-1 distnetmond: <greeks> 20 max jitter, last
1, max_rtt 444\n"..., 83) = 83
write(1, "Aug  8 17:10:10 sunfire-1 distnetmond: <greeks> 20 max jitter, last
6, max_rtt 444\n"..., 83) = 83
write(1, "Aug  8 17:10:11 sunfire-1 distnetmond: <insatgx> 2 max jitter, last
-2, max_rtt 427\n"..., 84) = 84
write(1, "Aug  8 17:10:11 sunfire-1 distnetmond: <greeks> 20 max jitter, last
-12, max_rtt 461\n"..., 85) = 85
write(1, "Aug  8 17:10:11 sunfire-1 distnetmond: <insatgx> 2 max jitter, last
-2, max_rtt 427\n"..., 84) = 84
write(1, "Aug  8 17:10:11 sunfire-1 distnetmond: <greeks> 21 max jitter, last
-13, max_rtt 461\n"..., 85) = 85
write(1, "Aug  8 17:10:12 sunfire-1 distnetmond: <insatgx> 2 max jitter, last
-2, max_rtt 444\n"..., 84) = 84
write(1, "Aug  8 17:10:12 sunfire-1 distnetmond: <greeks> 21 max jitter, last
-4, max_rtt 461\n"..., 84) = 84
write(1, "Aug  8 17:10:12 sunfire-1 distnetmond: <insatgx> 2 max jitter, last
-2, max_rtt 444\n"..., 84) = 84
write(1, "Aug  8 17:10:12 sunfire-1 distnetmond: <greeks> 21 max jitter, last
-13, max_rtt 461\n"..., 85) = 85
read(3, ""..., 0)                       = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=13752879, ...}) = 0
fcntl(3, F_GETFL)                       = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fcntl(3, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=13752879, ...}) = 0
clock_gettime(CLOCK_MONOTONIC, {255234, 516342978}) = 0
nanosleep({1, 0}, NULL)                 = 0
clock_gettime(CLOCK_MONOTONIC, {255235, 516520072}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=13753046, ...}) = 0
read(3, "Aug  8 17:10:13 sunfire-1 distnetmond: <insatgx> 2 max jitter, last 0,
max_rtt 444\nAug  8 17:10:13 sunfire-1 distnetmond: <greeks> 21 max jitter,
last -9, max_rtt 461\
write(1, "Aug  8 17:10:13 sunfire-1 distnetmond: <insatgx> 2 max jitter, last
0, max_rtt 444\nAug  8 17:10:13 sunfire-1 distnetmond: <greeks> 21 max jitter,
last -9, max_rtt 461
read(3, ""..., 8192)                    = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=13753046, ...}) = 0
clock_gettime(CLOCK_MONOTONIC, {255235, 516822345}) = 0
nanosleep({1, 0},  <unfinished ...>


busybox
open("/var/log/messages", O_RDONLY)     = 3
lseek(3, 0, SEEK_CUR)                   = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=13749328, ...}) = 0
read(3, "Aug  8 06:14:57 sunfire-1 syslog-ng[4507]: Configuration reload
request received, reloading configuration;\nAug  8 06:14:57 sunfire-1
distnetmond: <insatgx> 19 max jitt
lseek(3, 0, SEEK_CUR)                   = 8192
fstat(3, {st_mode=S_IFREG|0644, st_size=13749328, ...}) = 0
read(3, " 8 06:15:19 sunfire-1 distnetmond: <insatgx> 29 max jitter, last -15,
max_rtt 377\nAug  8 06:15:19 sunfire-1 distnetmond: <greeks> 8 max jitter, last
-5, max_rtt 400\nA
lseek(3, 0, SEEK_CUR)                   = 16384
fstat(3, {st_mode=S_IFREG|0644, st_size=13749328, ...}) = 0
read(3, "nd: <insatgx> 10 max jitter, last -9, max_rtt 380\nAug  8 06:15:42
sunfire-1 distnetmond: <greeks> 2 max jitter, last -2, max_rtt 403\nAug  8
06:15:43 sunfire-1 distnet
lseek(3, 0, SEEK_CUR)                   = 24576
fstat(3, {st_mode=S_IFREG|0644, st_size=13749328, ...}) = 0
read(3, "06:16:05 sunfire-1 distnetmond: <greeks> 13 max jitter, last -12,
max_rtt 401\nAug  8 06:16:06 sunfire-1 distnetmond: <insatgx> 8 max jitter,
last -7, max_rtt 380\nAug
lseek(3, 0, SEEK_CUR)                   = 32781
fstat(3, {st_mode=S_IFREG|0644, st_size=13749328, ...}) = 0
read(3, " jitter, last -10, max_rtt 401\nAug  8 06:16:29 sunfire-1 distnetmond:
<insatgx> 5 max jitter, last -5, max_rtt 379\nAug  8 06:16:29 sunfire-1
distnetmond: <greeks> 12
lseek(3, 0, SEEK_CUR)                   = 40973



I can attach full strace log


-- 
Configure bugmail: https://bugs.busybox.net/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are on the CC list for the bug.