Ticket 2848 - Please help understand how Elapsed is calculated by sacct
Summary: Please help understand how Elapsed is calculated by sacct
Status: RESOLVED INFOGIVEN
Alias: None
Product: Slurm
Classification: Unclassified
Component: Other (show other tickets)
Version: 15.08.12
Hardware: Linux Linux
: 4 - Minor Issue
Assignee: Dominik Bartkiewicz
QA Contact:
URL:
Depends on:
Blocks:
 
Reported: 2016-06-21 12:39 MDT by Sergey Meirovich
Modified: 2016-07-19 03:47 MDT (History)
0 users

See Also:
Site: AMAT
Slinky Site: ---
Alineos Sites: ---
Atos/Eviden Sites: ---
Confidential Site: ---
Coreweave sites: ---
Cray Sites: ---
DS9 clusters: ---
Google sites: ---
HPCnow Sites: ---
HPE Sites: ---
IBM Sites: ---
NOAA SIte: ---
NoveTech Sites: ---
Nvidia HWinf-CS Sites: ---
OCF Sites: ---
Recursion Pharma Sites: ---
SFW Sites: ---
SNIC sites: ---
Tzag Elita Sites: ---
Linux Distro: ---
Machine Name:
CLE Version:
Version Fixed:
Target Release: ---
DevPrio: ---
Emory-Cloud Sites: ---

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this ticket.
Description Sergey Meirovich 2016-06-21 12:39:30 MDT 
I am working on automatic classification (using python scikit-learn) of the jobs and further using these data for various reporting. I simply put classificated data into separated database and now using that cross joining slurm database with my database.

My problem is I could figure out how exactly Elapsed is calculated basing on data from slurm database.

Initially I thought that for any already finished job  this is simply (time_end - time_start - time_suspended) from job_table of step_table. That didn't happen to be true. Then I tried user_sec + sys_sec from step_table without luck.

Could you please shed a light on Elapsed formula?
Comment 1 Tim Wickberg 2016-06-21 15:18:15 MDT 
As you note, elapsed should be (time_end - time_begin) for the job, minus any suspend time.

Are you seeing something different?

Can you attach a chunk of "sacct --format=jobid,start,end,elapsed" where the numbers don't match up?
Comment 2 Sergey Meirovich 2016-06-21 23:06:28 MDT 
Hmm,

Looks like my errors appeared due to sometime start_time is 0

What is that?
Comment 3 Sergey Meirovich 2016-06-23 06:41:08 MDT 
Hi Tim,

Fund clear abnormaly in the db:

mysql>  SELECT id_job,job_db_inx,time_end,time_start,time_suspended,CONVERT(time_end,DECIMAL(65)) - CONVERT(time_start,DECIMAL(65)) - CONVERT(time_suspended,DECIMAL(65)) as t FROM austin_job_table WHERE time_start<>0 AND time_end<>0  ORDER BY t  LIMIT 3;
+--------+------------+------------+------------+----------------+-------------+
| id_job | job_db_inx | time_end   | time_start | time_suspended | t           |
+--------+------------+------------+------------+----------------+-------------+
|   5365 |       8460 | 1453748912 | 1453748510 |     1453748912 | -1453748510 |
|   5366 |       8461 | 1453748912 | 1453748510 |     1453748912 | -1453748510 |
|   5364 |       8459 | 1453748912 | 1453748510 |     1453748912 | -1453748510 |
+--------+------------+------------+------------+----------------+-------------+
3 rows in set (1.37 sec)

mysql> 
-bash-4.1$ sacct --format=jobid,start,end,elapsed,suspended -j 5364
       JobID               Start                 End    Elapsed  Suspended 
------------ ------------------- ------------------- ---------- ---------- 
5364                Jan 25 11:01        Jan 25 11:08   00:00:00 16825-19:08:32 
5364.batch          Jan 25 11:01        Jan 27 10:46 1-23:44:19   00:00:00 
5364.0              Jan 25 11:01        Jan 27 10:46 1-23:44:19   00:00:00 
-bash-4.1$ sacct --format=jobid,start,end,elapsed,suspended -j 5365
       JobID               Start                 End    Elapsed  Suspended 
------------ ------------------- ------------------- ---------- ---------- 
5365                Jan 25 11:01        Jan 25 11:08   00:00:00 16825-19:08:32 
5365.batch          Jan 25 11:01        Jan 27 10:47 1-23:45:23   00:00:00 
5365.0              Jan 25 11:01        Jan 27 10:47 1-23:45:23   00:00:00 
-bash-4.1$ sacct --format=jobid,start,end,elapsed,suspended -j 5366
       JobID               Start                 End    Elapsed  Suspended 
------------ ------------------- ------------------- ---------- ---------- 
5366                Jan 25 11:01        Jan 25 11:08   00:00:00 16825-19:08:32 
5366.batch          Jan 25 11:01        Jan 28  9:50 2-22:48:30   00:00:00 
5366.0              Jan 25 11:01        Jan 28  9:50 2-22:48:30   00:00:00 
-bash-4.1$
Comment 4 Sergey Meirovich 2016-06-23 07:04:12 MDT 
I reset these 3 time_suspended to 0 as they obviously odd...
Comment 6 Tim Wickberg 2016-07-08 12:54:37 MDT 
time_suspended is the timestamp of the most recent suspension, not a value. There's a separate table - $CLUSTER_suspend_table - that deals with the individual start/stop timestamps for the job.

Something does appear to be odd here - having the entries from $CLUSTER_suspend_table and logs from slurmctld may help narrow down the issue. My best guess, assuming everything else was working properly, is that the job completed right when it was due for suspension by the gang scheduler and some race condition resulted in these records. If you're able to get info from the database and logs it'd help locate such a bug.
Comment 12 Dominik Bartkiewicz 2016-07-11 08:41:06 MDT 
Hi

I know it's been a while, but could you send me slurmctld and slurmdbd logs from 25 till 28 January?

Dominik
Comment 13 Sergey Meirovich 2016-07-11 08:44:54 MDT 
Hi,

Unfortunately logs from 25 till 28 January have been already rotated over.

Let's probably close that case. If the issue re-occurs we could always re-open it.
Comment 14 Dominik Bartkiewicz 2016-07-19 03:47:37 MDT 
Marking resolved; please reopen if you notice this again.

Dominik