search

performancecopilot / pcp

Performance Co-Pilot
https://pcp.io
Other
962 stars 234 forks source link

Interpolation not effective in some cases #433

Open myllynen opened 6 years ago

myllynen commented 6 years ago

As discussed in https://groups.io/g/pcp/topic/6111366, when creating an archive with pmlogger(1) the prologue is logged ~0.02 seconds before the actual data and we see for example with pmdumptext(1) shows results being 10 minutes off and misses some records in the end. I'm providing a copypaste and a test archive to demonstrate this issue below.

$ pmdumplog -z -a test                                          
Note: timezone set to local timezone of host "test" from archive

Log Label (Log Format Version 2)
Performance metrics from host test
    commencing Fri Oct 20 10:36:00.416347 2017
    ending     Fri Oct 20 11:26:00.436134 2017
Archive timezone: EEST-3
PID for pmlogger: 6479

Descriptions for Metrics in the Log ...
PMID: 60.1.2 (mem.util.free)
    Data Type: 64-bit unsigned int  InDom: PM_INDOM_NULL 0xffffffff
    Semantics: instant  Units: Kbyte
PMID: 2.3.2 (pmcd.pmlogger.archive)
    Data Type: string  InDom: 2.1 0x800001
    Semantics: discrete  Units: none
PMID: 2.3.0 (pmcd.pmlogger.port)
    Data Type: 32-bit unsigned int  InDom: 2.1 0x800001
    Semantics: discrete  Units: none
PMID: 2.3.3 (pmcd.pmlogger.host)
    Data Type: string  InDom: 2.1 0x800001
    Semantics: discrete  Units: none

Instance Domains in the Log ...
InDom: 2.1
10:36:00.416347 1 instances
   6479 or "6479"

Temporal Index
        Log Vol    end(meta)     end(log)
10:36:00.416347       0          132          132
11:26:00.436134       0          403          528

[136 bytes]
10:36:00.416347 3 metrics
    2.3.3 (pmcd.pmlogger.host): inst [6479 or "6479"] value "localhost"
    2.3.0 (pmcd.pmlogger.port): inst [6479 or "6479"] value 4330
    2.3.2 (pmcd.pmlogger.archive): inst [6479 or "6479"] value "/home/testuser/pcptest/logger/test"

[52 bytes]
10:36:00.435851 1 metric
    60.1.2 (mem.util.free): value 6925664

[52 bytes]
10:46:00.436619 1 metric
    60.1.2 (mem.util.free): value 3764672

[52 bytes]
10:56:00.436598 1 metric
    60.1.2 (mem.util.free): value 3374424

[52 bytes]
11:06:00.436446 1 metric
    60.1.2 (mem.util.free): value 5832004

[52 bytes]
11:16:00.436239 1 metric
    60.1.2 (mem.util.free): value 5574748

[52 bytes]
11:26:00.436134 1 metric
    60.1.2 (mem.util.free): value 5685308
$ pmdumptext -z -a test -t 10min mem.util.free                  
Fri Oct 20 10:36:00 ?
Fri Oct 20 10:46:00 6925664.000
Fri Oct 20 10:56:00 3764672.000
Fri Oct 20 11:06:00 3374424.000
Fri Oct 20 11:16:00 5832004.000
Fri Oct 20 11:26:00 5574748.000
$

test-archive.tar.gz

Let's use this issue to document expectations and track possible fixes around this. Thanks.

kmcdonell commented 4 years ago

@myllynen I'm experimenting with a change to pmlogger that will defer writing the label records and the preamble (which is a synthetic pmResult) until the first real pmResult is seen, then using the timestamp from the first pmResult in the label records and the preamble (so we'll get two pmResults at the start with the same timestamp). This certainly fixes your pmdumptext example, but I need to be sure there are no other unexpected side-effects.

myllynen commented 3 years ago

@kmcdonell I have missed your comment here earlier. Did you have a chance to test this further, did you come across any side-effects? Thanks.