pmie negative deltas revisited...

[Nathan Scott <nathans@xxxxxxxxxx>]

Hi all,

Awhile ago I reported on pmie sleeping for negative time intervals,
noticed today a log with the newer diagnostics added - hope this is
of use... (these warnings repeat a fair bit ... can send the entire
log and rules file, offlist, if its of use?)

$ pcp
Performance Co-Pilot configuration on XXX:

 platform: Linux XXX 2.6.18-92.el5xen #1 SMP Tue Apr 29 13:31:30 EDT 2008 x86_64
 hardware: 4 cpus, 1 disk, 4196MB RAM
 timezone: EST-11
     pmcd: Version 3.4.0-1, 5 agents, 5 clients
     pmda: pmcd linux mmv aconex lockfiles
     pmie: XXX: /var/log/pcp/pmie/XXX/pmie.log

Log for pmie on XXX rotated Tue Dec  7 00:14:01 2010

pmie: PID = 10361, default host = XXX

Tue Dec  7 10:24:12 2010: Key Lock wait time 2.95 4.05 3.94 3.07 0.0127987
sleepTight: negative delay (-1.875555). sched=1291677857.597569, 
cur=1291677859.473124
Last sleepTight (eval) until: Tue Dec  7 10:24:12 2010.597568
Last Task dump @ 0xe24b9d0
  nth=0 delta=5.000 tick=7371 next=(nil) prev=(nil)
  eval time: Tue Dec  7 10:24:17 2010.597568
  retry time: Thu Jan  1 10:00:00 1970.000000
  host=XXX (up)
  rules:
    keylock
    dbcache
    failed_notification
    viewer_nuke
    viewer_clean
    garbage_vwr
    garbage_novwr
    preload_misses
    lockfiles
    dbconns
    threaddump
    profiler
    load
    pmda
    lsof
    swapout
    oprofile_clear
    oprofile_start
This sleepTight() entry: Tue Dec  7 10:24:19 2010.473118
Harvest children done: Tue Dec  7 10:24:19 2010.473124
Want sleepTight (eval) until: Tue Dec  7 10:24:17 2010.597568
This Task dump @ 0xe24b9d0
  nth=0 delta=5.000 tick=7371 next=(nil) prev=(nil)
  eval time: Tue Dec  7 10:24:17 2010.597568
  retry time: Thu Jan  1 10:00:00 1970.000000
  host=XXX (up)
  rules:
    keylock
    dbcache
    failed_notification
    viewer_nuke
    viewer_clean
    garbage_vwr
    garbage_novwr
    preload_misses
    lockfiles
    dbconns
    threaddump
    profiler
    load
    pmda
    lsof
    swapout
    oprofile_clear
    oprofile_start
Tue Dec  7 11:59:17 2010: Key Lock wait time 3.39 0.00939906 2.18 3.47 1.26
sleepTight: negative delay (-1.712029). sched=1291683562.597569, 
cur=1291683564.309598
Last sleepTight (eval) until: Tue Dec  7 11:59:17 2010.597568
Last Task dump @ 0xe24b9d0
  nth=0 delta=5.000 tick=8512 next=(nil) prev=(nil)
  eval time: Tue Dec  7 11:59:22 2010.597568
  retry time: Thu Jan  1 10:00:00 1970.000000
  host=XXX (up)
  rules:
    keylock
    dbcache
    failed_notification
    viewer_nuke
    viewer_clean
    garbage_vwr
    garbage_novwr
    preload_misses
    lockfiles
    dbconns
    threaddump
    profiler
    load
    pmda
    lsof
    swapout
    oprofile_clear
    oprofile_start
...


cheers.

-- 
Nathan