Underflow/overflow in wall time counter.

[tobigithub]

Hi, I ran the caffeine CID example with QCxMS (V5.0.3). Input:

>xtb2
>cid
>elab 60
>maxcoll 2
>esi
>pgas 0.132
>lchamb 0.12
>simmd 5000

For some of the output files I observed a negative number when minutes were counted, which is interesting to say the least.

>grep -Rin "wall time (min)"  --include 'qcxms.out'  TMPQCXMS/*/*

...
TMPQCXMS/TMP.605/qcxms.out:685: wall time (min)     30.29
TMPQCXMS/TMP.606/qcxms.out:693: wall time (min)     31.47
TMPQCXMS/TMP.607/qcxms.out:710: wall time (min)  -3545.61
TMPQCXMS/TMP.608/qcxms.out:463: wall time (min)     16.17
TMPQCXMS/TMP.609/qcxms.out:470: wall time (min)     17.79
TMPQCXMS/TMP.60/qcxms.out:547: wall time (min)     21.12
TMPQCXMS/TMP.610/qcxms.out:684: wall time (min)  -3549.49
TMPQCXMS/TMP.611/qcxms.out:778: wall time (min)  -3546.74
TMPQCXMS/TMP.612/qcxms.out:599: wall time (min)  -3550.60
TMPQCXMS/TMP.613/qcxms.out:683: wall time (min)  -3550.25
TMPQCXMS/TMP.614/qcxms.out:705: wall time (min)  -3545.17
TMPQCXMS/TMP.615/qcxms.out:488: wall time (min)  -3557.87
TMPQCXMS/TMP.616/qcxms.out:463: wall time (min)     16.07
TMPQCXMS/TMP.617/qcxms.out:700: wall time (min)  -3546.64
TMPQCXMS/TMP.618/qcxms.out:696: wall time (min)  -3548.47
TMPQCXMS/TMP.619/qcxms.out:831: wall time (min)  -3540.09
TMPQCXMS/TMP.61/qcxms.out:779: wall time (min)     36.04
TMPQCXMS/TMP.620/qcxms.out:488: wall time (min)  -3559.32
TMPQCXMS/TMP.621/qcxms.out:689: wall time (min)  -3548.62
TMPQCXMS/TMP.622/qcxms.out:680: wall time (min)  -3550.18
TMPQCXMS/TMP.623/qcxms.out:678: wall time (min)  -3550.58
TMPQCXMS/TMP.624/qcxms.out:681: wall time (min)  -3550.64
TMPQCXMS/TMP.625/qcxms.out:761: wall time (min)  -3550.72
TMPQCXMS/TMP.62/qcxms.out:759: wall time (min)     32.48
TMPQCXMS/TMP.63/qcxms.out:466: wall time (min)     18.70
TMPQCXMS/TMP.64/qcxms.out:681: wall time (min)     30.97
TMPQCXMS/TMP.65/qcxms.out:702: wall time (min)     35.87
...

Might be a scheduler issues, still I am curious how a negative number could occur, the scheduler log files has an issue, still the task was running fine.

Auks API request failed : krb5 cred : unable to read credential cache
Starting at Tue Aug  3 08:03:48 PDT 2021
Running on 1 nodes.
Running  tasks.

Job started at  Tue Aug 3 08:03:48 PDT 2021
/TMPQCXMS/TMP.610
Job ended at  Tue Aug 3 08:33:27 PDT 2021

Also the qcxms.out confirms the times:

Tue Aug  3 08:03:48 PDT 2021

                      *********************************************
                      *                                           *
                      *            Q   C   x   M   S              *
                      *                                           *
                      *                  V5.0.3                    *
                      *                                           *
                      *                S. Grimme                  *
                      * Mulliken Center for Theoretical Chemistry *
                      *             Universitaet Bonn             *
                      *                  2008-21                  *
                      *        Jun 10 15:00:00 CEST 2021          *
                      *                                           *
                      *********************************************

QCxMS is free software: you can redistribute it and/or modify it under
...

  mass                formula                  q pop   spin    |q IPB|  diss time (ps)
 M=195.20            H11C8N4O2   610   2   1   1.000   0.000   1.000    0.000

 -------------------------------------------------
  Last MD is finished. All is written out
 -------------------------------------------------

 ------------------------------------------
     No fragmentation in the simulation!
    Increase energy or time of sampling.
 ------------------------------------------

 wall time (min)  -3549.49
 # of QC calls       14680

Tue Aug  3 08:33:27 PDT 2021
                      --- QCxMS V5.0.3 Jun 10 15:00:00 CEST 2021     ---
 normal termination of QCxMS

Spectrum looks fine, but with 2 collisions only (commonly 6) fewer fragments are observed, which is normal. Not sure how the time is calculated, might be a non-issue for QCxMS, but more related to the scheduler.

[JayTheDog]

I've changed the timing routine between 5.0.0 and 5.0.3, but I did not encounter any negative numbers. The routine calls the system_clock and the cpu_time, which are intrinsic operations, but depend on the system that runs the program, so the scheduler can be an issue in this respect.

Anyways, I found that the variables were not initially initialize, which is now done for version 5.1.0. If you still find this issue, I can take a closer look, but might depend on your system.

[tobigithub]

Thanks. Closed.