Thanks Marko.  You mentioned this was 100% reproducible on IRC?  Can you attach the archive and add a reproducer recipe (which metrics, archive offsets, etc).

Created attachment 743045 [details]
example pcp archive

With the attached archive this can be reproduced as follows:

1. pmchart -t 1m -a gfs
2. Add both the available metrics as their own charts
3. Start playback from Time Controls, let it run for few seconds
4. Press Stop

We should not rule out the possibility that libpcp may be a victim here, rather than the cuplrit

1. valgrind reports lots of bad looking errors from Qt and pmchart before the failure

2. $ valgrind pmdumptext -t 1m -a gfs gfs.inodes gfs.fmb

runs to completion with no errors reported by valgrind.

3. And in another test,

$ pmchart -Dall -t 1m -a gfs

dies with a segv as soon as the first metric is selected then Apply ... although this is also deep inside __pmLogFetchInterp() like the original case.

Have traced this back to fairly close to the root cause now, discussing with the author of the code in question regarding how best to fix it.

Ignore my case 3. above ... the segv is due to a botch in the interp.c diagnostic code that is exposed with -Dall at the start of the archive.

I have a fix for this.

No closer yet to a diagnosis for the original problem.

(I can't reproduce this on fedora18, pcp3.8, pcp-gui 1.5.8.)

(To get a sense of what's going on in pcpland, consider using systemtap:

# yum install systemtap pcp-debuginfo
# stap /usr/share/doc/systemtap*/examples/*/para-callgraph.stp 'process("/usr/lib/libpcp.so.3").function("*")'

(I can't reproduce this on rhel6, epel pcp3.8, epel pcp-gui 1.5.6.  Valgrind only complains about what seems like an off-by-one error in libqwt:

==31172== Invalid read of size 8
==31172==    at 0x8114BE6: QwtCPointerData::sample(unsigned int) const (qpoint.h:247)
==31172==    by 0x80BBA87: SamplingCurve::drawSeries(QPainter*, QwtScaleMap const&, QwtScaleMap const&, QRectF const&, int, int) const (qwt_plot_seriesitem.h:135)
==31172==    by 0x810B04D: QwtPlotAbstractSeriesItem::draw(QPainter*, QwtScaleMap const&, QwtScaleMap const&, QRectF const&) const (qwt_plot_seriesitem.cpp:88)
==31172==    by 0x80FCC22: QwtPlot::drawItems(QPainter*, QRectF const&, QwtScaleMap const*) const (qwt_plot.cpp:517)
==31172==    by 0x80FCDB3: QwtPlot::drawCanvas(QPainter*) (qwt_plot.cpp:490)
==31172==    by 0x811106D: QwtPlotCanvas::drawCanvas(QPainter*, bool) (qwt_plot_canvas.cpp:893)
==31172==    by 0x81117FE: QwtPlotCanvas::paintEvent(QPaintEvent*) (qwt_plot_canvas.cpp:754)
==31172==    by 0x4B46CEA: QWidget::event(QEvent*) (qwidget.cpp:8144)
==31172==    by 0x4F140D3: QFrame::event(QEvent*) (qframe.cpp:557)
==31172==    by 0x81104CA: QwtPlotCanvas::event(QEvent*) (qwt_plot_canvas.cpp:712)
==31172==    by 0x4AF3DDB: QApplicationPrivate::notify_helper(QObject*, QEvent*) (qapplication.cpp:4300)
==31172==    by 0x4AFA57C: QApplication::notify(QObject*, QEvent*) (qapplication.cpp:4265)
==31172==  Address 0x8bfcb90 is 0 bytes after a block of size 2,344 alloc'd
==31172==    at 0x4007282: malloc (vg_replace_malloc.c:270)
==31172==    by 0x80B8E08: GroupControl::init(int, int, timeval*, timeval*) (groupcontrol.cpp:55)
==31172==    by 0x80707CE: main (main.cpp:752)

A bit more about this archive (which is unusual in one important respect):

The archive span is almost 4 days:
$ pmdumplog -L gfs
Log Label (Log Format Version 2)
Performance metrics from host mmyllyne.csb
  commencing Thu Apr 18 20:40:00.000 2013
  ending     Mon Apr 22 20:00:00.000 2013

and there are samples every 5 minutes
$ pmdumplog gfs | head -5

20:40:00.000  245.0.1 (gfs.fmb): value 3712689

20:45:00.000  245.0.1 (gfs.fmb): value 3712699

$ pmdumplog gfs | grep '^[0-2]' | wc -l
1146

1146 = 4 * 24 * 12 - 8 (for the 40 min diff between the minutes at the start and end)

and there are no mark records so this is from one continuous pmlogger execution
$ pmdumplog gfs | grep mark

and gfs.fmb appears in every sample but one, while gfs.inodes appears in only one sample
$ pmdumplog gfs gfs.fmb | grep '^[0-2]' | wc -l
1145
$ pmdumplog gfs gfs.inodes | grep '^[0-2]' | wc -l
1

and gfs.inodes is only at the very end
$ pmdumplog gfs | tail -5
19:55:00.000  245.0.1 (gfs.fmb): value 3757337

20:00:00.000  245.0.1 (gfs.fmb): value 3757320

20:00:00.000  245.0.2 (gfs.inodes): value 103860

This does not explain the bug.  But gfs.inodes will _always_ be interpolated to have the value 103860 with a t_prior of -1 and no v_prior and t_next will be the last 20:00:00 timestamp from the archive and v_next will be 103860.

This is sufficiently unusual that it does help explain why this has not been reported before.

So Marko could you please add to the bug explaining how the gfs archive was created?

I'll keep digging ...

Ken - it will be an archive created through pmlogimport (Perl API, which wraps the C API).  Interesting that you found that too, in another now-possibly-related bug I got to the point of wondering if the archive (which is probably the same archive) was corrupt or created not-quite-right by log import (somehow).

That other bug is 956716.  Marko, can you provide us the script and csv data for just this archive (appropriately anonymised if its customer data - ISTR it was from your own or a lab system though).

Ken - note also the very wierd behaviour with this archive with pmdumplog.  Try both forwards, and then backwards (-r) and note how the names/pmidsseem to spontaneously change!?!  Still trying to get to the bottom of that behaviour, but maybe we need to be looking closely at exactly what pmimport is doing when its writing the metadata? - its a common theme.


nathans@smash:~/gfs$ pmdumplog -a -r gfs | tail
20:50:00.000  245.0.2 (gfs.inodes): value 102799

[52 bytes]
20:45:00.000  245.0.2 (gfs.inodes): value 102798

[52 bytes]
20:40:00.000  245.0.2 (gfs.inodes): value 102808

[52 bytes]
20:40:00.000  245.0.1 (gfs.fmb): value 3712689

nathans@smash:~/gfs$ pmdumplog -a gfs | tail
19:50:00.000  245.0.1 (gfs.fmb): value 3757334

[52 bytes]
19:55:00.000  245.0.1 (gfs.fmb): value 3757337

[52 bytes]
20:00:00.000  245.0.1 (gfs.fmb): value 3757320

[52 bytes]
20:00:00.000  245.0.2 (gfs.inodes): value 103860

Created attachment 750139 [details]
stap trace

Frank, our package versions are slightly different (perhaps you're also on 32-bit given the path in your stap example), I'm using:

pcp-3.8.0-1.el6.x86_64
pcp-gui-1.5.8-2.el6.x86_64

I'm attaching the stap output (+ backtrace dumped on terminal at the end of the file). The stap output weights no less than 1.62M lines.

Created attachment 750140 [details]
archive script + CSVs

Ken, Nathan,

thanks for your insights - I had actually already deleted the script since it was a test script used with test data from a test lab :) But I rewrote it from memory and by using it with the CSV files included in the attachment I can still reproduce the crash.

The script is obviously not doing what I was expecting but based on your comment 9 and comment 10 it's bit unclear to me is this merely a bug in the script or might there be perhaps something not-quite-right with pmlogimport?

OK ... problem found!

The script appears to _append_ pmResults for gfs.fmb to the output archive after adding pmResults for gfs.inodes and the time ranges for the two spreadsheets are the same.  This means the time goes backwards in the archive and then repeats all over again.

Checking this size of the archive ... gfs.0 contains 119212 bytes and the pmResults records are 52 bytes long (correct size for one one metric with one double value), so (119212-132)/52 = 2290, which is exactly TWICE the number of samples we expect.

Because of the way pmFetchArchive and the lower level log read routines work, we do not detect the archive is botched and this _exactly_ explains the schizo behavior Nathan reported for pmdumplog forwards vs backwards.

The perl script needs to process the two .csv files in parallel, matching up the timestamps, then adding _both_ metrics to the one pmResult.

We need a pmlogcheck utility to detect this sort of botch.

Can we please have permission to include the gfs.* archive in the PCP QA suite?

> OK ... problem found!

Well done!  Yes, it all makes sense.

> We need a pmlogcheck utility to detect this sort of botch.

Let me know what you plan to fix and if you want to throw anything over the fence for me to do, lemme know.

> Can we please have permission to include the gfs.* archive in the PCP QA suite?

Its publicly available on bugzilla, and not customer data as Marko mentioned - so I'm hopeful he wont have any issues with it being used for automated testing.

> Can we please have permission to include the gfs.* archive in the PCP QA
> suite?

Yes, please go ahead.

*** Bug 956716 has been marked as a duplicate of this bug. ***

pcp-3.8.1-1.el6 has been submitted as an update for Fedora EPEL 6.
https://admin.fedoraproject.org/updates/pcp-3.8.1-1.el6

pcp-3.8.1-1.el6 has been pushed to the Fedora EPEL 6 stable repository.  If problems still persist, please make note of it in this bug report.

Closing out manually - issue has been long since fixed.