Re: Re: [alpine-devel] Attempting to debug C++ library and command via valgrind

[Rich Felker <dalias@libc.org>]

On Wed, Jul 09, 2014 at 11:50:08PM -0700, Isaac Dunham wrote:
> On Thu, Jul 10, 2014 at 12:47:16AM -0400, Rich Felker wrote:
> > On Wed, Jul 09, 2014 at 09:13:49PM -0700, Isaac Dunham wrote:
> > > On Wed, Jul 09, 2014 at 10:30:11AM -0500, Jeff Pohlmeyer wrote:
> > > > On Tue, Jul 8, 2014 at 11:39 PM, Isaac Dunham wrote:
> > > > 
> > > > > I've been trying to get Sword 1.7.3 (crosswire.org/sword) running on Alpine.
> > > > > valgrind was recommended, but I can't get valgrind to run the command properly.
> > > > > But when I do this, diatheke errors out:
> > > > > diatheke: cannot load -b: No such file or directory
> > > > 
> > > > 
> > > > I think it's a problem with the way valgrind tries to run musl's program loader.
> > > > 
> > > > Try adding "/lib/ld-musl-i386.so.1" to the command line, just before
> > > > the prgram name,
> > > > e.g.
> > > > 
> > > > valgrind --leak-check=full --track-origins=yes \
> > > >  --keep-stacktraces=alloc-and-free \
> > > >   /lib/ld-musl-i386.so.1 \
> > > >    diatheke  -b KJV -k Ps117
> > > 
> > > Thanks, this works for me.
> > > 
> > > Of course it really runs slow and spits out a ton of information;
> > > the log is over 400 kb at 5464 lines. (I suppose sending it to these lists
> > > might be inappropriate, given the size...)
> > 
> > If you have a reasonable place to dump the file you could just send a
> > link to the list. But I think you're getting ahead of things. What
> > actual failure is the program exhibiting? (Crash? Incorrect or no
> > output? Error messages?) Depending on what happens, a gdb backtrace or
> > an strace log may be more useful than the valgrind output.
> > 
> Incorrect output: specifically, it repeats (most of) the last line of the
> intended output.
> strace was my first resort, but it did not seem helpful to me;
> since the program in question is using a large C++ library to access a
> compressed text with a good deal of processing in memory, I could not
> figure out how the syscalls mapped to code.
> When I asked on the sword-devel list, valgrind was recommended.
> 
> The output compresses down to ~4k when bzipped, so I guess it
> isn't a big issue.
> 
> Now I looked at strace again; here's what I found:
> -100k lines of output, compressing to 500 kb (!).
> -the relevant bit is likely this:
> 
> open("/home/idunham/.sword/modules/texts/ztext/kjv/ot.bzz", O_RDWR|O_LARGEFILE) = 5
> _llseek(5, 0, [0], SEEK_SET)            = 0
> _llseek(5, 1261942, [1261942], SEEK_SET) = 0
> mmap2(NULL, 180224, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb57d5000
> read(5, "x\234\354\275\353\222\343F\222&\372*\30\375\3325\253\321\20w\240\324S2iz\325\225\323\322hl"..., 177216) = 177216
> mmap2(NULL, 180224, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb57a9000
> mmap2(NULL, 3547136, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5447000
> mmap2(NULL, 1024000, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb534d000
> munmap(0xb5447000, 3547136)             = 0
> mmap2(NULL, 1024000, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb56af000
> munmap(0xb57d5000, 180224)              = 0
> ioctl(1, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0xbfc21fa4) = -1 ENOTTY (Not a tty)
> writev(1, [{"Psalms 117:1: O praise the LORD,"..., 75}, {"\n", 1}], 2Psalms 117:1: O praise the LORD, all ye nations: praise him, all ye people.
> ) = 76
> _llseek(3, 164840, [164840], SEEK_SET)  = 0
> read(3, "\23\0\0\0", 4)                 = 4
> read(3, "\207\204\f\0", 4)              = 4
> read(3, "\34\1", 2)                     = 2
> _llseek(3, 164850, [164850], SEEK_SET)  = 0
> read(3, "\23\0\0\0", 4)                 = 4
> read(3, "\243\205\f\0", 4)              = 4
> read(3, "'\2", 2)                       = 2
> _llseek(3, 164850, [164850], SEEK_SET)  = 0
> read(3, "\23\0\0\0", 4)                 = 4
> read(3, "\243\205\f\0", 4)              = 4
> read(3, "'\2", 2)                       = 2
> _llseek(3, 164850, [164850], SEEK_SET)  = 0
> read(3, "\23\0\0\0", 4)                 = 4
> read(3, "\243\205\f\0", 4)              = 4
> read(3, "'\2", 2)                       = 2
> munmap(0xb56af000, 1024000)             = 0
> munmap(0xb57a9000, 180224)              = 0
> munmap(0xb534d000, 1024000)             = 0
> close(4)                                = 0
> close(5)                                = 0
> close(3)                                = 0
> writev(1, [{"Psalms 117:2: For his merciful k"..., 246}, {NULL, 0}], 2Psalms 117:2: For his merciful kindness is great toward us: and the truth of the LORD endureth for ever. Praise ye the LORD. 
> : For his merciful kindness is great toward us: and the truth of the LORD endureth for ever. Praise ye the LORD. 
> (KJV)
> ) = 246
> 
> Which looks like it's going through a loop twice when it reaches the exit condition.

The fact that it's using writev suggests strongly that the output is
being written via musl's stdio (to stdout, since it's fd #1) rather
than via some other mechanism, but it could be C++ iostreams using
stdio as their backend. It's hard to say whether this is due to
corruption of the FILE state or the actual calling code writing the
output twice. When I get a chance I can look over your valgrind output
a bit but FYI the way I would go about debugging this is putting a
breakpoint in __stdout_write conditional on f->fd==1 and looking at
the backtrace for how it's reached.

Rich