[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[Bug gas/15295] New: gas rebuffer_line() routine (listing.c) issues exce
|
From: |
jtison at us dot ibm.com |
|
Subject: |
[Bug gas/15295] New: gas rebuffer_line() routine (listing.c) issues excessive read syscalls |
|
Date: |
Fri, 22 Mar 2013 13:44:46 +0000 |
http://sourceware.org/bugzilla/show_bug.cgi?id=15295
Bug #: 15295
Summary: gas rebuffer_line() routine (listing.c) issues
excessive read syscalls
Product: binutils
Version: 2.20
Status: NEW
Severity: normal
Priority: P2
Component: gas
AssignedTo: address@hidden
ReportedBy: address@hidden
Classification: Unclassified
Created attachment 6939
--> http://sourceware.org/bugzilla/attachment.cgi?id=6939
1.7 MiB of GPL C code that produces 460 KLOC of assembler.
A monolithic C program, attached, when compiled at -O2 and stopped at the
assembler output phase (-S), produces a monolithic assembler source file. No
surprises. --host==--build==--target=s390-ibm-linux
as-2.19 combines the assembler and C listings using about 1500 read syscalls.
The assembler code I used was obtained with:
gcc -S -g -O2 -o offldr.s offldr.i
as-2.20 appears to have refactored most of listing.c. The rebuffer_line()
function issues an ftell() to see what its last position was, then immediately
issues an fseek(0,SEEK_SET) and re-reads all of the current file (C source is
the most painful) from its very beginning. as-2.20 uses a little over a million
read syscalls to achieve the same goal that 2.19 accomplished in less than 1500
syscalls. fd 5 appears to be reused for both the assembler source and the C
language source & header files; whenever the use of the fd changes, each file
is read from offset zero instead of its last known position.
I tried a fast patch (see below) to as-2.20 to change what I thought the
offensive behavior was, and managed to reduce the read syscalls to around
27,000; but the HLL and assembly now seem out of sync. I have to confess I'm
not familiar with this code and I might have missed something important, or
maybe there's a better way to correct this behavior. I've sent it along only as
a suggestion of what might need correction.
Times and strace summaries look like this:
time as-2.19 -o offldr.o2.o -alshd=offldr.o2.lst offldr.o2.s
real 0m2.071s
user 0m1.606s
sys 0m0.142s
strace -c as-2.19 -o offldr.o2.o -alshd=offldr.o2.lst offldr.o2.s
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
55.44 0.029016 22 1333 write
19.98 0.010457 7 1490 read
12.82 0.006711 13 498 195 open
3.75 0.001963 7 300 munmap
1.62 0.000849 849 1 unlink
1.58 0.000828 2 388 brk
1.31 0.000683 2 322 mmap
1.03 0.000537 2 303 close
0.81 0.000423 2 192 189 stat
0.48 0.000249 1 303 fstat
0.45 0.000235 235 1 execve
0.44 0.000231 1 312 lseek
0.20 0.000106 27 4 fadvise64
0.08 0.000042 7 6 mprotect
0.01 0.000004 4 1 1 access
0.00 0.000001 1 1 getrusage
0.00 0.000001 1 1 lstat
------ ----------- ----------- --------- --------- ----------------
100.00 0.052336 5456 385 total
time as-2.20 -o offldr.o2.o -alshd=offldr.o2.lst offldr.o2.s
real 4m34.289s
user 4m27.146s
sys 0m3.857s
strace -c as-2.20 -o offldr.o2.o -alshd=offldr.o2.lst offldr.o2.s
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
87.56 3.093972 3 1020659 read
3.44 0.121514 9 13246 munmap
3.25 0.114720 9 13316 67 open
1.95 0.068848 43 1599 write
1.80 0.063709 5 13249 close
0.98 0.034803 3 13267 mmap
0.58 0.020548 1 26204 lseek
0.37 0.012923 1 13249 fstat
0.02 0.000794 2 388 brk
0.02 0.000703 176 4 fadvise64
0.01 0.000505 505 1 unlink
0.01 0.000235 235 1 execve
0.01 0.000206 3 64 63 stat
0.00 0.000047 8 6 mprotect
0.00 0.000006 6 1 1 access
0.00 0.000002 1 2 fcntl
0.00 0.000001 1 1 getrusage
0.00 0.000001 1 1 lstat
------ ----------- ----------- --------- --------- ----------------
100.00 3.533537 1115258 131 total
(as-2.20-1 is patched like so, I'm sure there is something wrong with it, a fix
like this cannot be this simple:)
///////////////////////////// cut here ///////////////////////////////////
--- binutils-2.20.1/gas/listing.c.old 2010-01-14 05:48:31.000000000 -0500
+++ binutils-2.20.1/gas/listing.c 2013-03-18 14:35:22.000000000 -0400
@@ -544,7 +544,6 @@ rebuffer_line (file_info_type * file,
unsigned int size)
{
unsigned int count = 0;
- unsigned int current_line = 1;
char * p = buffer;
long pos;
int c;
@@ -577,14 +576,8 @@ rebuffer_line (file_info_type * file,
fseek (last_open_file, file->pos, SEEK_SET);
}
- /* Remember where we are in the current file. */
- pos = ftell (last_open_file);
-
- /* Go back to the beginning. */
- fseek (last_open_file, 0, SEEK_SET);
-
/* Skip lines prior to the one we are interested in. */
- while (current_line < linenum)
+ while (file->linenum < linenum)
{
/* fgets only stops on newlines and has a size limit,
so we read one character at a time instead. */
@@ -594,7 +587,7 @@ rebuffer_line (file_info_type * file,
}
while (c != EOF && c != '\n' && c != '\r');
- ++ current_line;
+ ++ file->linenum;
if (c == '\r' || c == '\n')
{
///////////////////////////////////////////////////////////////////
I must confess to not knowing what I'm doing inside listing.c, I am merely
taking a stab at what I think some of the more egregious calls might be. I
leave the final solution to you, this patch is not a suggested fix. If at all
possible, could we pick up reading the last user of fd 5 perhaps a few bytes
behind its last used position?
Here's how this patched code runs:
time as-2.20-1 -o offldr.o2.o -alshd=offldr.o2.lst offldr.o2.s
real 0m3.045s
user 0m2.396s
sys 0m0.422s
strace -c as-2.20-1 -o offldr.o2.o -alshd=offldr.o2.lst offldr.o2.s
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
33.32 0.169969 6 26781 read
18.35 0.093618 7 13136 67 open
17.72 0.090398 7 13066 munmap
10.11 0.051572 33 1547 write
7.10 0.036214 3 13069 close
6.77 0.034531 3 13087 mmap
3.46 0.017665 1 19489 6405 lseek
2.65 0.013509 1 13069 fstat
0.25 0.001268 3 388 brk
0.15 0.000782 782 1 unlink
0.06 0.000305 305 1 execve
0.04 0.000204 3 64 63 stat
0.01 0.000042 11 4 fadvise64
0.01 0.000037 6 6 mprotect
0.00 0.000005 5 1 1 access
0.00 0.000003 2 2 fcntl
0.00 0.000001 1 1 getrusage
0.00 0.000001 1 1 lstat
------ ----------- ----------- --------- --------- ----------------
100.00 0.510124 113713 6536 total
This PR goes with an e-mail I sent to the bug-binutils mailing list the day
before yesterday.
I talked with IBM Legal yesterday about shipping out our licensed code as a
test case. They denied me permission to do so. Instead, as a test case, I found
an even larger GPL program that displays even greater contrasts: oggenc.c (Ogg
Vorbis encoding) which is licensed under GPL v2. You should have no trouble
seeing the read syscalls nor the effects on assembly time.
To create your test case on a native s390x-ibm-linux gcc compiler equipped with
binutils-2.21, do this:
gcc -O2 -S -g -o oggenc.s oggenc.c
as -o oggenc.o -alshd=oggenc.lst oggenc.s # Make sure you get a listing!
Here's what I see for timings & strace summaries with all three assemblers:
time as-2.19 -o oggenc.o -alshd=oggenc.lst oggenc.s
real 0m7.311s
user 0m6.924s
sys 0m0.359s
time as-2.20 -o oggenc.o -alshd=oggenc.lst oggenc.s
real 13m24.879s
user 13m8.837s
sys 0m9.649s
time as-2.20-1 -o oggenc.o -alshd=oggenc.lst oggenc.s
real 0m11.241s
user 0m8.960s
sys 0m0.700s
strace -c as-2.19 -o oggenc.o -alshd=oggenc.lst oggenc.s
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
69.24 0.120428 22 5478 write
11.94 0.020768 8 2653 read
10.39 0.018070 34 533 262 open
2.30 0.004003 1001 4 fadvise64
1.54 0.002672 2672 1 unlink
1.46 0.002538 2 1292 brk
1.13 0.001958 7 270 munmap
0.61 0.001060 4 256 252 stat
0.41 0.000715 2 292 mmap
0.30 0.000524 2 271 close
0.30 0.000516 516 1 execve
0.14 0.000244 1 271 fstat
0.14 0.000236 39 6 mprotect
0.11 0.000193 1 280 lseek
0.00 0.000008 8 1 1 access
0.00 0.000002 2 1 getrusage
0.00 0.000001 1 1 lstat
------ ----------- ----------- --------- --------- ----------------
100.00 0.173936 11611 515 total
strace -c as-2.20 -o oggenc.o -alshd=oggenc.lst oggenc.s
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
94.00 14.906169 5 2757563 read
1.45 0.229871 12 18646 munmap
1.15 0.181850 32 5692 write
1.09 0.172328 9 18846 199 open
0.70 0.110274 6 18647 close
0.66 0.104281 3 37032 lseek
0.54 0.086084 5 18667 mmap
0.35 0.055968 3 18647 fstat
0.03 0.005022 4 1292 brk
0.02 0.003031 3031 1 unlink
0.01 0.001359 7 192 189 stat
0.00 0.000668 668 1 execve
0.00 0.000050 13 4 fadvise64
0.00 0.000037 6 6 mprotect
0.00 0.000008 8 1 1 access
0.00 0.000006 3 2 fcntl
0.00 0.000004 4 1 getrusage
0.00 0.000004 4 1 lstat
------ ----------- ----------- --------- --------- ----------------
100.00 15.857014 2895241 389 total
2.75 MM read syscalls!!
strace -c as-2.20-1 -o oggenc.o -alshd=oggenc.lst oggenc.s
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
33.59 0.195420 5 38180 read
21.15 0.123062 22 5684 write
14.83 0.086272 5 18198 munmap
12.64 0.073509 4 18398 199 open
6.05 0.035180 2 18219 mmap
4.70 0.027358 2 18199 close
3.24 0.018825 1 27208 8934 lseek
2.53 0.014738 1 18199 fstat
0.50 0.002934 2934 1 unlink
0.42 0.002448 2 1292 brk
0.17 0.000990 5 192 189 stat
0.13 0.000775 775 1 execve
0.04 0.000226 57 4 fadvise64
0.00 0.000029 5 6 mprotect
0.00 0.000007 7 1 1 access
0.00 0.000003 2 2 fcntl
0.00 0.000002 2 1 getrusage
0.00 0.000001 1 1 lstat
------ ----------- ----------- --------- --------- ----------------
100.00 0.581779 163786 9323 total
If there is any more information you need, please don't hesitate to contact me.
Thanks.
--
Configure bugmail: http://sourceware.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are on the CC list for the bug.
- [Bug gas/15295] New: gas rebuffer_line() routine (listing.c) issues excessive read syscalls,
jtison at us dot ibm.com <=
- [Bug gas/15295] gas rebuffer_line() routine (listing.c) issues excessive read syscalls, nickc at redhat dot com, 2013/03/25
- [Bug gas/15295] gas rebuffer_line() routine (listing.c) issues excessive read syscalls, jtison at us dot ibm.com, 2013/03/25
- [Bug gas/15295] gas rebuffer_line() routine (listing.c) issues excessive read syscalls, cvs-commit at gcc dot gnu.org, 2013/03/26
- [Bug gas/15295] gas rebuffer_line() routine (listing.c) issues excessive read syscalls, nickc at redhat dot com, 2013/03/26
- [Bug gas/15295] gas rebuffer_line() routine (listing.c) issues excessive read syscalls, jtison at us dot ibm.com, 2013/03/26