performancecopilot
Interpolation not effective in some cases
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
$
Let's use this issue to document expectations and track possible fixes around this. Thanks.
@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.
@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.