GDB using a lot of CPU time and writing a lot to disk on startup

GDB using a lot of CPU time and writing a lot to disk on startup

[Nick Savoiu]

I'm using GDB 6.8 (x86_64-unknown-linux-gnu) from within KDevelop 3.5.4. I've noticed that for some projects GDB uses 1 minute of CPU time and seems to do a lot of disk writing during this time.

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 3439 nsavoiu   16   0  600m 589m 2536 S    0 15.2   1:13.64 gdb

I can't really figure out why this is happening and could use some help tracking it down.

I used pstack every second until the debugging actually starts and here are all the unique #0 locations in the pstack output.

#0  0x0000000000446d16 in msymbol_hash_iw ()
#0  0x0000000000446f97 in lookup_minimal_symbol ()
#0  0x00000000004bfda0 in symbol_natural_name ()
#0  0x00000000004bffe4 in find_pc_sect_psymtab ()
#0  0x00000000004c0118 in find_pc_sect_psymbol ()
#0  0x00000000004fd755 in bcache_data ()
#0  0x000000000050d11a in dwarf2_lookup_abbrev ()
#0  0x0000000000610c67 in d_print_comp ()
#0  0x00000035aae28250 in __ctype_b_loc () from /lib64/tls/libc.so.6
#0  0x00000035aae68ced in _int_free () from /lib64/tls/libc.so.6
#0  0x00000035aaeb94a5 in _xstat () from /lib64/tls/libc.so.6
#0  0x00000035aaeb9545 in _lxstat () from /lib64/tls/libc.so.6
#0  0x00000035aaeb9832 in __open_nocancel () from /lib64/tls/libc.so.6
#0  0x00000035aaebe18f in poll () from /lib64/tls/libc.so.6

Of 461 calls 418 are:

#0  0x00000035aaeb94a5 in _xstat () from /lib64/tls/libc.so.6

Thanks,
Nick

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Paul Pluzhnikov]

On Mon, Apr 20, 2009 at 3:40 PM, Nick Savoiu <savoiu@yahoo.com> wrote:

> I'm using GDB 6.8 (x86_64-unknown-linux-gnu) from within KDevelop
> 3.5.4. I've noticed that for some projects GDB uses 1 minute of CPU time
> and seems to do a lot of disk writing during this time.

AFAIU, GDB doesn't write anything to disk (unless you ask it to with gcore
that is).

I don't see anything in your message which would substantiate your claim
of disk writing either. How did you come to conclusion that GDB writes
anything to disk?

>  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
>  3439 nsavoiu   16   0  600m 589m 2536 S    0 15.2   1:13.64 gdb
>
> I can't really figure out why this is happening and could use some help tracking it down.
>
> I used pstack every second until the debugging actually starts and here
> are all the unique #0 locations in the pstack output.
>
> #0  0x0000000000446d16 in msymbol_hash_iw ()
> #0  0x0000000000446f97 in lookup_minimal_symbol ()
> #0  0x00000000004bfda0 in symbol_natural_name ()
> #0  0x00000000004bffe4 in find_pc_sect_psymtab ()
> #0  0x00000000004c0118 in find_pc_sect_psymbol ()
> #0  0x00000000004fd755 in bcache_data ()
> #0  0x000000000050d11a in dwarf2_lookup_abbrev ()
> #0  0x0000000000610c67 in d_print_comp ()
> #0  0x00000035aae28250 in __ctype_b_loc () from /lib64/tls/libc.so.6
> #0  0x00000035aae68ced in _int_free () from /lib64/tls/libc.so.6
> #0  0x00000035aaeb94a5 in _xstat () from /lib64/tls/libc.so.6
> #0  0x00000035aaeb9545 in _lxstat () from /lib64/tls/libc.so.6
> #0  0x00000035aaeb9832 in __open_nocancel () from /lib64/tls/libc.so.6
> #0  0x00000035aaebe18f in poll () from /lib64/tls/libc.so.6

This output is bogus.

It sounds like your GDB is compiled with -fomit-frame-pointers (default
on x86_64 with optimization), and pstack doesn't know how to unwind stack
for such code.

Does your inferior program (the one you are debugging) have many (as in
thousands) of shared libraries? If so, you might want to watch this thread:
http://sourceware.org/ml/gdb-patches/2009-04/msg00548.html

If not, you may want to build GDB from source with 'CFLAGS = -g -pg -O0', run
it on your inferior program, and collect the resulting profile with gprof.

-- 
Paul Pluzhnikov

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Daniel Jacobowitz]

On Mon, Apr 20, 2009 at 04:39:56PM -0700, Paul Pluzhnikov wrote:
> > I used pstack every second until the debugging actually starts and here
> > are all the unique #0 locations in the pstack output.
> >
> > #0  0x0000000000446d16 in msymbol_hash_iw ()
> > #0  0x0000000000446f97 in lookup_minimal_symbol ()
> > #0  0x00000000004bfda0 in symbol_natural_name ()
> > #0  0x00000000004bffe4 in find_pc_sect_psymtab ()
> > #0  0x00000000004c0118 in find_pc_sect_psymbol ()
> > #0  0x00000000004fd755 in bcache_data ()
> > #0  0x000000000050d11a in dwarf2_lookup_abbrev ()
> > #0  0x0000000000610c67 in d_print_comp ()
> > #0  0x00000035aae28250 in __ctype_b_loc () from /lib64/tls/libc.so.6
> > #0  0x00000035aae68ced in _int_free () from /lib64/tls/libc.so.6
> > #0  0x00000035aaeb94a5 in _xstat () from /lib64/tls/libc.so.6
> > #0  0x00000035aaeb9545 in _lxstat () from /lib64/tls/libc.so.6
> > #0  0x00000035aaeb9832 in __open_nocancel () from /lib64/tls/libc.so.6
> > #0  0x00000035aaebe18f in poll () from /lib64/tls/libc.so.6
> 
> This output is bogus.

I thought that too the first time I read it - but see his description
of the output (above) again :-)

Nick, it sounds to me like you're debugging something that you haven't
got enough RAM for - is the disk I/O your swap space?

-- 
Daniel Jacobowitz
CodeSourcery

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Paul Pluzhnikov]

On Mon, Apr 20, 2009 at 4:48 PM, Daniel Jacobowitz <drow@false.org> wrote:
> On Mon, Apr 20, 2009 at 04:39:56PM -0700, Paul Pluzhnikov wrote:
>> > I used pstack every second until the debugging actually starts and here
>> > are all the unique #0 locations in the pstack output.
...
>> This output is bogus.
>
> I thought that too the first time I read it - but see his description
> of the output (above) again :-)

Oops. I see it now; thanks.

So most of the time (481 of 461) GDB is blocked in stat. Not a big surprize.

> Nick, it sounds to me like you're debugging something that you haven't
> got enough RAM for - is the disk I/O your swap space?

I don't (yet) see any evidence for swapping either. Do you?

Cheers,
-- 
Paul Pluzhnikov

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Nick Savoiu]

----- Original Message ----
> From: Paul Pluzhnikov <ppluzhnikov@google.com>
> To: Nick Savoiu <savoiu@yahoo.com>
> Cc: gdb@sourceware.org
> Sent: Monday, April 20, 2009 4:39:56 PM
> Subject: Re: GDB using a lot of CPU time and writing a lot to disk on startup
> 
> On Mon, Apr 20, 2009 at 3:40 PM, Nick Savoiu wrote:
> 
> > I'm using GDB 6.8 (x86_64-unknown-linux-gnu) from within KDevelop
> > 3.5.4. I've noticed that for some projects GDB uses 1 minute of CPU time
> > and seems to do a lot of disk writing during this time.
> 
> AFAIU, GDB doesn't write anything to disk (unless you ask it to with gcore
> that is).

Paul,

That's
what I thought too. I should have said that I suspect GDB to be the one
writing to the disk but I could not find a way to verify/prove that.
The best I could to I track CPU usage for each process in the chain

  kdevelop(2381)---gdb(7810)---kernel(7816)

From 16:50:28 to 17:00:37 (start of debugging session until break in main) here are the stats from 'top':

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
2381 nsavoiu   15   0  594m 424m  34m S    0 10.9   0:49.13 kdevelop
2381 nsavoiu   16   0  594m 424m  34m S    1 10.9   0:49.31 kdevelop

7810 nsavoiu   16   0  140m 130m 2472 S   22  3.4   0:03.92 gdb
7810 nsavoiu   16   0  634m 622m 2536 S   73 16.0   1:51.12 gdb

7816 nsavoiu   25   0  153m 138m  61m T    0  3.6   0:08.23 kernel
7816 nsavoiu   25   0  153m 138m  61m T    0  3.6   0:08.23 kernel

so my best guess was GDB given where the CPU times went. No other processes were running actively and there was enough memory

Mem:   3975148k total,  3372012k used,   603136k free,    86136k buffers
Swap:  8385848k total,   756112k used,  7629736k free,  1407932k cached

so swapping should not be an issue.

The
thing is that pretty much from the moment that I click the 'debug'
button in KDevelop the disk chugs continuously for as long as you can
see from above info (~10 minutes in this case). Using KSysGuard shows
it as 99% being writes (beats me what gets written).

> > I used pstack every second until the debugging actually starts and here
> > are all the unique #0 locations in the pstack output.
> >
> > #0  0x0000000000446d16 in msymbol_hash_iw ()
> > #0  0x0000000000446f97 in lookup_minimal_symbol ()
> > #0  0x00000000004bfda0 in symbol_natural_name ()
> > #0  0x00000000004bffe4 in find_pc_sect_psymtab ()
> > #0  0x00000000004c0118 in find_pc_sect_psymbol ()
> > #0  0x00000000004fd755 in bcache_data ()
> > #0  0x000000000050d11a in dwarf2_lookup_abbrev ()
> > #0  0x0000000000610c67 in d_print_comp ()
> > #0  0x00000035aae28250 in __ctype_b_loc () from /lib64/tls/libc.so.6
> > #0  0x00000035aae68ced in _int_free () from /lib64/tls/libc.so.6
> > #0  0x00000035aaeb94a5 in _xstat () from /lib64/tls/libc.so.6
> > #0  0x00000035aaeb9545 in _lxstat () from /lib64/tls/libc.so.6
> > #0  0x00000035aaeb9832 in __open_nocancel () from /lib64/tls/libc.so.6
> > #0  0x00000035aaebe18f in poll () from /lib64/tls/libc.so.6
> 
> This output is bogus.

These are only the unique top entries from pstack. Here's a typical full stack:

#0  0x00000035aaeb94a5 in _xstat () from /lib64/tls/libc.so.6
#1  0x00000000004aa827 in is_regular_file ()
#2  0x00000000004aa965 in openp ()
#3  0x00000000004aae12 in find_and_open_source ()
#4  0x00000000004aaff0 in psymtab_to_fullname ()
#5  0x00000000004bf581 in lookup_partial_symtab ()
#6  0x00000000004bf427 in lookup_symtab ()
#7  0x00000000004cd578 in symtab_from_filename ()
#8  0x00000000004cc8e0 in decode_line_1 ()
#9  0x00000000004a36c5 in breakpoint_re_set_one ()
#10 0x00000000004dee60 in catch_errors ()
#11 0x00000000004a393b in breakpoint_re_set ()
#12 0x00000000004c5917 in new_symfile_objfile ()
#13 0x00000000004c5b36 in symbol_file_add_with_addrs_or_offsets ()
#14 0x00000000004c5c85 in symbol_file_add_from_bfd ()
#15 0x000000000045889e in symbol_add_stub ()
#16 0x00000000004dee60 in catch_errors ()
#17 0x0000000000458946 in solib_read_symbols ()
#18 0x0000000000458c74 in solib_add ()
#19 0x00000000004d4d8f in handle_inferior_event ()
#20 0x00000000004d349a in wait_for_inferior ()
#21 0x00000000004d3207 in proceed ()
#22 0x00000000004cfd8e in run_command_1 ()
#23 0x000000000047d7cf in do_cfunc ()
#24 0x000000000047f73e in cmd_func ()
#25 0x0000000000448852 in execute_command ()
#26 0x0000000000489f77 in mi_execute_async_cli_command ()
#27 0x0000000000489cee in mi_cmd_execute ()
#28 0x0000000000489a1a in captured_mi_execute_command ()
#29 0x00000000004dec96 in catch_exception ()
#30 0x0000000000489b5f in mi_execute_command ()
#31 0x00000000004e34fb in gdb_readline2 ()
#32 0x00000000004e2c1b in stdin_event_handler ()
#33 0x00000000004e1b7c in handle_file_event ()
#34 0x00000000004e15cf in process_event ()
#35 0x00000000004e1621 in gdb_do_one_event ()
#36 0x00000000004dee60 in catch_errors ()
#37 0x00000000004e164a in start_event_loop ()
#38 0x00000000004df31f in current_interp_command_loop ()
#39 0x0000000000442989 in captured_command_loop ()
#40 0x00000000004dee60 in catch_errors ()
#41 0x00000000004434b6 in captured_main ()
#42 0x00000000004dee60 in catch_errors ()
#43 0x0000000000443694 in gdb_main ()
#44 0x0000000000442947 in main ()

Thanks for the link. I get hit by it too but I only have ~200 .solibs.

Nick

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Mark Kettenis]

> Date: Mon, 20 Apr 2009 17:17:46 -0700 (PDT)
> From: Nick Savoiu <savoiu@yahoo.com>
> 
>   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
> 2381 nsavoiu   15   0  594m 424m  34m S    0 10.9   0:49.13 kdevelop
> 2381 nsavoiu   16   0  594m 424m  34m S    1 10.9   0:49.31 kdevelop
> 
> 7810 nsavoiu   16   0  140m 130m 2472 S   22  3.4   0:03.92 gdb
> 7810 nsavoiu   16   0  634m 622m 2536 S   73 16.0   1:51.12 gdb

Heh, if memory consumption is to blame, kdevelop is about as guilty as
gdb ;)

> 7816 nsavoiu   25   0  153m 138m  61m T    0  3.6   0:08.23 kernel
> 7816 nsavoiu   25   0  153m 138m  61m T    0  3.6   0:08.23 kernel
> 
> so my best guess was GDB given where the CPU times went. No other processes were running actively and there was enough memory
> 
> Mem:   3975148k total,  3372012k used,   603136k free,    86136k buffers
> Swap:  8385848k total,   756112k used,  7629736k free,  1407932k cached
> 
> so swapping should not be an issue.

Well, your system *is* using swap.  Are you running Linux?  I wouldn't
be surprised if it is swapping out kdevelop because gdb is the active
application and is reading in a lot of debugging info.

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Nick Savoiu]

----- Original Message ----

> From: Mark Kettenis <mark.kettenis@xs4all.nl>
> > From: Nick Savoiu 
> > 
> >   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
> > 2381 nsavoiu   15   0  594m 424m  34m S    0 10.9   0:49.13 kdevelop
> > 2381 nsavoiu   16   0  594m 424m  34m S    1 10.9   0:49.31 kdevelop
> > 
> > 7810 nsavoiu   16   0  140m 130m 2472 S   22  3.4   0:03.92 gdb
> > 7810 nsavoiu   16   0  634m 622m 2536 S   73 16.0   1:51.12 gdb
> 
> Heh, if memory consumption is to blame, kdevelop is about as guilty as
> gdb ;)
> 
> > 7816 nsavoiu   25   0  153m 138m  61m T    0  3.6   0:08.23 kernel
> > 7816 nsavoiu   25   0  153m 138m  61m T    0  3.6   0:08.23 kernel
> > 
> > so my best guess was GDB given where the CPU times went. No other processes 
> were running actively and there was enough memory
> > 
> > Mem:   3975148k total,  3372012k used,   603136k free,    86136k buffers
> > Swap:  8385848k total,   756112k used,  7629736k free,  1407932k cached
> > 
> > so swapping should not be an issue.
> 
> Well, your system *is* using swap.  Are you running Linux?  I wouldn't
> be surprised if it is swapping out kdevelop because gdb is the active
> application and is reading in a lot of debugging info.

Mark, I highly doubt that it's swapping. The system has plenty of memory (the snapshot above is at the end of the run) and swap usage had not changed throughout. More so the memory amounts involved should not account for 10 minutes of continuous disk writes on a machine that is otherwise very fast (both in CPU and disk).

What's puzzling is that an identical project on the same machine does not exhibit the same behavior. GDB gets to the 'main' breakpoint in 15-20 seconds with very mild disk activity. Is there a way to make gdb dump a trace/log of its activities?

Nick

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Eli Zaretskii]

> Date: Tue, 21 Apr 2009 09:26:43 -0700 (PDT)
> From: Nick Savoiu <savoiu@yahoo.com>
> 
> > Well, your system *is* using swap.  Are you running Linux?  I wouldn't
> > be surprised if it is swapping out kdevelop because gdb is the active
> > application and is reading in a lot of debugging info.
> 
> Mark, I highly doubt that it's swapping. The system has plenty of memory (the snapshot above is at the end of the run) and swap usage had not changed throughout. More so the memory amounts involved should not account for 10 minutes of continuous disk writes on a machine that is otherwise very fast (both in CPU and disk).

There should be no need to argue about this: just look at the disk LED
when the problematic behavior kicks in.

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Jonas Maebe]

On 21 Apr 2009, at 21:04, Eli Zaretskii wrote:

> There should be no need to argue about this: just look at the disk LED
> when the problematic behavior kicks in.

Or run "iostat 1" in a separate shell (you may have to install it  
explicitly before it's available).


Jonas

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Nick Savoiu]

This is what I get for the whole time that gdb is starting up:

Device:    rrqm/s wrqm/s   r/s   w/s  rsec/s  wsec/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util
sda          0.00 2073.47  0.00 1056.12    0.00 25036.73     0.00 12518.37    23.71     0.94    0.89   0.89  93.67
sdb          0.00 2073.47  0.00 1056.12    0.00 25036.73     0.00 12518.37    23.71     0.95    0.90   0.89  94.29

There are some reads from time to time but the writes are a constant.
Is there a way to determine the process that actually does the writing?

Thanks,
Nick



----- Original Message ----
> From: Jonas Maebe <jonas.maebe@elis.ugent.be>
> To: Eli Zaretskii <eliz@gnu.org>
> Cc: Nick Savoiu <savoiu@yahoo.com>; gdb@sourceware.org
> Sent: Tuesday, April 21, 2009 12:52:05 PM
> Subject: Re: GDB using a lot of CPU time and writing a lot to disk on startup
> 
> 
> On 21 Apr 2009, at 21:04, Eli Zaretskii wrote:
> 
> > There should be no need to argue about this: just look at the disk LED
> > when the problematic behavior kicks in.
> 
> Or run "iostat 1" in a separate shell (you may have to install it explicitly 
> before it's available).
> 
> 
> Jonas

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Nick Savoiu]

Forgot to mention, the 'swap used' does not change during this time so it's highly unlikely that swapping is the issue. Given the write rate even if swapping was happening it should not take more than a few seconds.

Nick



----- Original Message ----
> From: Nick Savoiu <savoiu@yahoo.com>
> To: gdb@sourceware.org
> Sent: Wednesday, April 22, 2009 10:21:24 AM
> Subject: Re: GDB using a lot of CPU time and writing a lot to disk on startup
> 
> 
> This is what I get for the whole time that gdb is starting up:
> 
> Device:    rrqm/s wrqm/s   r/s   w/s  rsec/s  wsec/s    rkB/s    wkB/s avgrq-sz 
> avgqu-sz   await  svctm  %util
> sda          0.00 2073.47  0.00 1056.12    0.00 25036.73     0.00 12518.37    
> 23.71     0.94    0.89   0.89  93.67
> sdb          0.00 2073.47  0.00 1056.12    0.00 25036.73     0.00 12518.37    
> 23.71     0.95    0.90   0.89  94.29
> 
> There are some reads from time to time but the writes are a constant.
> Is there a way to determine the process that actually does the writing?
> 
> Thanks,
> Nick
> 
> 
> 
> ----- Original Message ----
> > From: Jonas Maebe 
> > To: Eli Zaretskii 
> > Cc: Nick Savoiu ; gdb@sourceware.org
> > Sent: Tuesday, April 21, 2009 12:52:05 PM
> > Subject: Re: GDB using a lot of CPU time and writing a lot to disk on startup
> > 
> > 
> > On 21 Apr 2009, at 21:04, Eli Zaretskii wrote:
> > 
> > > There should be no need to argue about this: just look at the disk LED
> > > when the problematic behavior kicks in.
> > 
> > Or run "iostat 1" in a separate shell (you may have to install it explicitly 
> > before it's available).
> > 
> > 
> > Jonas

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Michael Snyder]

Nick Savoiu wrote:
> Forgot to mention, the 'swap used' does not change during this time so it's highly unlikely that swapping is the issue. Given the write rate even if swapping was happening it should not take more than a few seconds.

Forgive me if this has already been asked, but...
is there any chance that you have a stray .gdbinit file
with some odd command in it, such as "maint print symbols"?

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Jonas Maebe]

On 22 Apr 2009, at 19:21, Nick Savoiu wrote:

> This is what I get for the whole time that gdb is starting up:
>
> Device:    rrqm/s wrqm/s   r/s   w/s  rsec/s  wsec/s    rkB/s    wkB/ 
> s avgrq-sz avgqu-sz   await  svctm  %util
> sda          0.00 2073.47  0.00 1056.12    0.00 25036.73     0.00  
> 12518.37    23.71     0.94    0.89   0.89  93.67
> sdb          0.00 2073.47  0.00 1056.12    0.00 25036.73     0.00  
> 12518.37    23.71     0.95    0.90   0.89  94.29
>
> There are some reads from time to time but the writes are a constant.
> Is there a way to determine the process that actually does the  
> writing?

You can probably run strace on gdb to verify whether or not it is gdb  
(and if so, where it is writing to). I don't know of a way to check  
this in a system-wide way on Linux though (on Mac OS X, you could use  
fs_usage).


Jonas

Re: GDB using a lot of CPU time and writing a lot to disk on startup

[Toby Haynes]

Nick Savoiu <savoiu@yahoo.com> wrote on 22/04/2009 01:21:24 PM:
> There are some reads from time to time but the writes are a constant.
> Is there a way to determine the process that actually does the writing?

pidstat (part of the sysstat package) can report on which processes are 
producing disk I/O on Linux kernels 2.6.20 and later. For example, to 
monitor which processes are doing I/O over the next sixty seconds with 
reports every 10 seconds.

pidstat -d -t 10 6

Cheers,
Toby Haynes