Who's insane: gdb or I?

Who's insane: gdb or I?

[Bernd Jendrissek]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

I'm busy trying to hunt down a problem with INN (2.3.3), and at one point 
I thought I might have found a compiler bug.  But nooo... (more below)

1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
(gdb) s
1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
(gdb) s
1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
(gdb) s
1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
(gdb) s
1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
(gdb) s
1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
(gdb) list
1079            return;
1080        }
1081        if (PERMaccessconf->nnrpdoverstats) {
1082            gettimeofday(&etv, NULL);
1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
1085        }
1086
1087        if (av[1] != NULL)
1088            Reply("%d %s fields follow\r\n", NNTP_OVERVIEW_FOLLOWS_VAL, av[1]);
(gdb) print OVERtime
$26 = 0
      ######### I can understand this if OVERtime is still in a register...
(gdb) print etv
$27 = {tv_sec = 1025700128, tv_usec = 739014}
(gdb) print etv stv
A parse error in expression, near `'.
(gdb) print etv, stv
$28 = {tv_sec = 1025700032, tv_usec = 32372}
(gdb) print etv
$29 = {tv_sec = 1025700128, tv_usec = 739014}
(gdb) print stv
$30 = {tv_sec = 1025700032, tv_usec = 32372}

objdump -S nnrpd of the relevant part:

    if (PERMaccessconf->nnrpdoverstats) {
 804cb25:       a1 e8 9b 06 08          mov    0x8069be8,%eax
 804cb2a:       83 78 74 00             cmpl   $0x0,0x74(%eax)
 804cb2e:       74 48                   je     804cb78 <CMDxover+0x15c>
        gettimeofday(&etv, NULL);
 804cb30:       83 c4 f8                add    $0xfffffff8,%esp
 804cb33:       6a 00                   push   $0x0
 804cb35:       8d 5d d0                lea    0xffffffd0(%ebp),%ebx
 804cb38:       53                      push   %ebx
 804cb39:       e8 b6 d9 ff ff          call   804a4f4 <_init+0x780>
        OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
 804cb3e:       8b 45 d8                mov    0xffffffd8(%ebp),%eax
 804cb41:       8b 4d d0                mov    0xffffffd0(%ebp),%ecx
 804cb44:       29 c1                   sub    %eax,%ecx
        OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
 804cb46:       8b 45 dc                mov    0xffffffdc(%ebp),%eax
 804cb49:       8b 73 04                mov    0x4(%ebx),%esi
 804cb4c:       69 c9 e8 03 00 00       imul   $0x3e8,%ecx,%ecx
 804cb52:       29 c6                   sub    %eax,%esi
 804cb54:       bb d3 4d 62 10          mov    $0x10624dd3,%ebx
 804cb59:       89 f0                   mov    %esi,%eax
 804cb5b:       f7 eb                   imul   %ebx,%eax
 804cb5d:       03 0d b0 9b 06 08       add    0x8069bb0,%ecx
 804cb63:       c1 fa 06                sar    $0x6,%edx
 804cb66:       89 f0                   mov    %esi,%eax
 804cb68:       c1 f8 1f                sar    $0x1f,%eax
 804cb6b:       29 c2                   sub    %eax,%edx
 804cb6d:       01 d1                   add    %edx,%ecx
 804cb6f:       89 0d b0 9b 06 08       mov    %ecx,0x8069bb0
    }
 804cb75:       83 c4 10                add    $0x10,%esp

Which all seems fine.

Why did gdb tell me that the "OVERtime+=..." part happened several times
over?  A bad interaction with CFLAGS="... -O2 ..."?  Still, there are no
jumps in the generated assembly...  And why would gdb's idea of the
"current" line-number cycle between 1083 and 1084?

Bernd Jendrissek

- -- 
berndj@users.sourceforge.net is probably better to bookmark than any
employer-specific email address I may have appearing in the headers.
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.0.4 (GNU/Linux)
Comment: For info see http://www.gnupg.org

iD8DBQE9Ivjt/FmLrNfLpjMRAhK2AJ9Lb7wjqA1Oj4V2CS9JWrF7n1DavwCfSt55
sgKfxWFsdH++XtlnjRS350A=
=u+rm
-----END PGP SIGNATURE-----

Re: Who's insane: gdb or I?

[Eli Zaretskii]

On Wed, 3 Jul 2002, Bernd Jendrissek wrote:

> Why did gdb tell me that the "OVERtime+=..." part happened several times
> over?

Because compiler optimizations move code around, so that the machine 
instructions generated for those two lines are interleaved.

Simply get used to this.  I usually wait until the line shjown by GDB is 
after the one I'm interested in, and then print the relevant variables.

Re: Who's insane: gdb or I?

[Kris Warkentin]

> On Wed, 3 Jul 2002, Bernd Jendrissek wrote:
>
> > Why did gdb tell me that the "OVERtime+=..." part happened several times
> > over?
>
> Because compiler optimizations move code around, so that the machine
> instructions generated for those two lines are interleaved.
>
> Simply get used to this.  I usually wait until the line shjown by GDB is
> after the one I'm interested in, and then print the relevant variables.

I get this all the time too so I usually debug code compiled without
optimization.  Unfortunately if you're chasing an optimization bug all bets
are off and, like Bernd said, you just have to get used to it.

cheers,

Kris

Re: Who's insane: gdb or I?

[Carlo Wood]

On Wed, Jul 03, 2002 at 03:15:47PM +0200, Bernd Jendrissek wrote:
> 1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
> (gdb) s
> 1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
> (gdb) s
> 1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
> (gdb) s
> 1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;

Which compiler version are you using?
Can you show the *.s file of this part that is being
generated?  (Add -save-temps to the gcc/g++ line that generates
the *.o file; it will also generate a *.s file then).
Does the same thing happen when you use -gstabs or -gdwarf-2
instead of just -g?

-- 
Carlo Wood <carlo@alinoe.com>

Re: Who's insane: gdb or I?

[Bernd Jendrissek]

On Wed, Jul 03, 2002 at 03:15:47PM +0200, Bernd Jendrissek wrote:
> 1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
> (gdb) s
> 1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
> (gdb) s
> 1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
> (gdb) s
> 1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
> (gdb) s
> 1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
> (gdb) s
> 1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
> (gdb) list
> 1079            return;
> 1080        }
> 1081        if (PERMaccessconf->nnrpdoverstats) {
> 1082            gettimeofday(&etv, NULL);
> 1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
> 1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
> 1085        }

I then wondered why gdb hops between lines 1083 and 1084 a few times.

>     if (PERMaccessconf->nnrpdoverstats) {
>  804cb25:       a1 e8 9b 06 08          mov    0x8069be8,%eax
>  804cb2a:       83 78 74 00             cmpl   $0x0,0x74(%eax)
>  804cb2e:       74 48                   je     804cb78 <CMDxover+0x15c>
>         gettimeofday(&etv, NULL);
>  804cb30:       83 c4 f8                add    $0xfffffff8,%esp
>  804cb33:       6a 00                   push   $0x0
>  804cb35:       8d 5d d0                lea    0xffffffd0(%ebp),%ebx
>  804cb38:       53                      push   %ebx
>  804cb39:       e8 b6 d9 ff ff          call   804a4f4 <_init+0x780>
>         OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
>  804cb3e:       8b 45 d8                mov    0xffffffd8(%ebp),%eax
>  804cb41:       8b 4d d0                mov    0xffffffd0(%ebp),%ecx
>  804cb44:       29 c1                   sub    %eax,%ecx
>         OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
>  804cb46:       8b 45 dc                mov    0xffffffdc(%ebp),%eax
>  804cb49:       8b 73 04                mov    0x4(%ebx),%esi
>  804cb4c:       69 c9 e8 03 00 00       imul   $0x3e8,%ecx,%ecx
>  804cb52:       29 c6                   sub    %eax,%esi
>  804cb54:       bb d3 4d 62 10          mov    $0x10624dd3,%ebx
>  804cb59:       89 f0                   mov    %esi,%eax
>  804cb5b:       f7 eb                   imul   %ebx,%eax
>  804cb5d:       03 0d b0 9b 06 08       add    0x8069bb0,%ecx
>  804cb63:       c1 fa 06                sar    $0x6,%edx
>  804cb66:       89 f0                   mov    %esi,%eax
>  804cb68:       c1 f8 1f                sar    $0x1f,%eax
>  804cb6b:       29 c2                   sub    %eax,%edx
>  804cb6d:       01 d1                   add    %edx,%ecx
>  804cb6f:       89 0d b0 9b 06 08       mov    %ecx,0x8069bb0
>     }
>  804cb75:       83 c4 10                add    $0x10,%esp

I am happy with the explanation that I should get used to this when running
optimized code under gdb.  With a look at the assembly (disassembled from
the actual binary) I can convince myself that the alternation between lines
1083 and 1084 is due to fancy instruction scheduling and strength reduction
on gcc's part.  (gcc 2.95.2 BTW, and I know it's ancient.  But it works.)

Thanks to all who looked at this.  Unless anyone else thinks there's
something wrong here, I'm not too bothered about it.  At -O2 I think I
deserve to be confused by gdb! :)

Carlo, do you still want me to look at -gstabs vs. -gdwarf?

bernd

-- 
berndj@users.sourceforge.net is probably better to bookmark than any
employer-specific email address I may have appearing in the headers.

Re: Who's insane: gdb or I? (Answer: I am)

[Bernd Jendrissek]

Okay, I think I'm convinced that this is simply normal -O2 behaviour.

On Wed, Jul 03, 2002 at 03:15:47PM +0200, Bernd Jendrissek wrote:
> 1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
> (gdb) s
> 1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
> (gdb) s
> 1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
> (gdb) s
> 1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
> (gdb) s
> 1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
> (gdb) s
> 1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
> (gdb) list
> 1079            return;
> 1080        }
> 1081        if (PERMaccessconf->nnrpdoverstats) {
> 1082            gettimeofday(&etv, NULL);
> 1083            OVERtime+=(etv.tv_sec - stv.tv_sec) * 1000;
> 1084            OVERtime+=(etv.tv_usec - stv.tv_usec) / 1000;
> 1085        }

For those still interested, here's the assembly generated by gcc -save-temps
at -O2.  (Complete gcc options: -g -O2 -save-temps)

        movl PERMaccessconf,%eax
        cmpl $0,116(%eax)
        je .L799
.stabn 68,0,1082,.LM674-CMDxover
.LM674:
        addl $-8,%esp
        pushl $0
        leal -48(%ebp),%ebx
        pushl %ebx
        call gettimeofday
.stabn 68,0,1083,.LM675-CMDxover
.LM675:
        movl -40(%ebp),%eax
        movl -48(%ebp),%ecx
        subl %eax,%ecx
.stabn 68,0,1084,.LM676-CMDxover
.LM676:
        movl -36(%ebp),%eax
        movl 4(%ebx),%esi
.stabn 68,0,1083,.LM677-CMDxover
.LM677:
        imull $1000,%ecx,%ecx
.stabn 68,0,1084,.LM678-CMDxover
.LM678:
        subl %eax,%esi
        movl $274877907,%ebx
        movl %esi,%eax
        imull %ebx
.stabn 68,0,1083,.LM679-CMDxover
.LM679:
        addl OVERtime,%ecx
.stabn 68,0,1084,.LM680-CMDxover
.LM680:
        sarl $6,%edx
        movl %esi,%eax
        sarl $31,%eax
        subl %eax,%edx
        addl %edx,%ecx
        movl %ecx,OVERtime
.stabn 68,0,1085,.LM681-CMDxover
.LM681:
        addl $16,%esp
.L799:

So it appears the bouncing between lines 1083 and 1084 really is due to
interleaving of instructions.  Thanks for everyone's help; I consider this
resolved.

-- 
berndj@users.sourceforge.net is probably better to bookmark than any