Isilon: Job restarting long-running final tasks
Summary: Jobs are not showing progression due to long-running final tasks.
Symptoms
This issue can be seen on all jobs, most commonly marking jobs(Collect, IntegrityScan) and restriping jobs(SmartPools, AB/ABL, FP/FPL).
System jobs may not show progression while working on the final few tasks per phase.
Frequent discarding task results are seen when reviewing isi_job_d.log as the tasks are restarted.
This can lead to the job never completing, as one or more final tasks are unable to complete before being deactivated.
This occurs for several reasons such as when a higher priority job in the same exclusion set begins to run.
It can also be due to the limit of running jobs being reached, and a newer higher priority job beginning to run.
Other possible issues could be the job engine itself or cluster issues such as locking contention, node splits, node reboots/panics, system performance, and other possible causes.
Cause
Check for the job going waiting or running that would cause state changes in the job, and tasks to restart.
If you see a high number of waiting or running status changes, then look at the job to confirm the Priority.
If other jobs starting have a higher priority (1 being the highest priority), then it can cause the job to go to waiting.
To check live:
isi job events list --job-id=<JobID>
isi_for_array -sQ 'grep -hi "<JobName>.*Run\|<JobName>.*Wait" /var/log/messages' |sort -u |tail
To check in logs:
zgrep -h '<JobName>.*Run\|<JobName>.*Wait' */varlog.tar/log/messages* |grep <JobID>|sort -u |tail
Sometimes the same task ID is seen restarting frequently, and unable to complete successfully.
Potentially there are several task IDs restarting frequently.
In either case, ensure that the job is not being put into a waiting or paused status causing the discarded tasks with previous steps.
Check for deactivated or discarded tasks that could be due to job engine throttling.
To check live:
isi_for_array -sQ 'grep -hi "deactivat\|discard" /var/log/isi_job_d.log' |grep <JobName> | sort -u | tail
To check in logs:
grep -hi "deactivat\|discard" *-*/varlog.tar/log/isi_job_d.log* |grep <JobName> |sort -u|tail
In this example, the same task ID being discarded for the FlexProtectLin job looks at "tid=28-1" in the output:
[martid32@elvis 2024-10-29_20-31]$ zgrep -hi "deactivat\|discard" *-*/varlog.tar/log/isi_job_d.log* |grep 'FlexProtectLin jid=6894' |sort -u |tail
2024-10-10T06:01:53.217905-05:00 <3.6> CLUSTER-22(id22) isi_job_d[92144]: Worker 12 Stopped: (task_state_clean, 614) FlexProtectLin[6894].0: Discarding unsent task result: { task_result={ jtid=FlexProtectLin jid=6894 phase=0 tid=28-1 rid=57916 ready=false errors=[] } data={ lins=0 files=0 dirs=0 blocks=0 lins_processed=0 sins=0 sins_processed=0 } start_linsid=0::INVALID end_linsid=0::INVALID }
2024-10-11T11:50:02.236664-05:00 <3.6> CLUSTER-5(id5) isi_job_d[79762]: Worker 77 Stopped: (task_state_clean, 614) FlexProtectLin[6894].0: Discarding unsent task result: { task_result={ jtid=FlexProtectLin jid=6894 phase=0 tid=28-1 rid=60525 ready=false errors=[] } data={ lins=0 files=0 dirs=0 blocks=0 lins_processed=0 sins=0 sins_processed=0 } start_linsid=0::INVALID end_linsid=0::INVALID }
2024-10-11T16:24:26.930667-05:00 <3.6> CLUSTER-7(id7) isi_job_d[68876]: Worker 21 Stopped: (task_state_clean, 614) FlexProtectLin[6894].0: Discarding unsent task result: { task_result={ jtid=FlexProtectLin jid=6894 phase=0 tid=28-1 rid=58508 ready=false errors=[] } data={ lins=0 files=0 dirs=0 blocks=0 lins_processed=0 sins=0 sins_processed=0 } start_linsid=0::INVALID end_linsid=0::INVALID }
2024-10-11T19:14:46.876445-05:00 <3.6> CLUSTER-11(id11) isi_job_d[28510]: Worker 39 Stopped: (task_state_clean, 614) FlexProtectLin[6894].0: Discarding unsent task result: { task_result={ jtid=FlexProtectLin jid=6894 phase=0 tid=28-1 rid=60665 ready=false errors=[] } data={ lins=0 files=0 dirs=0 blocks=0 lins_processed=0 sins=0 sins_processed=0 } start_linsid=0::INVALID end_linsid=0::INVALID }
2024-10-11T20:30:49.232915-05:00 <3.6> CLUSTER-8(id8) isi_job_d[58489]: Worker 20 Stopped: (task_state_clean, 614) FlexProtectLin[6894].0: Discarding unsent task result: { task_result={ jtid=FlexProtectLin jid=6894 phase=0 tid=28-1 rid=74387 ready=false errors=[] } data={ lins=0 files=0 dirs=0 blocks=0 lins_processed=0 sins=0 sins_processed=0 } start_linsid=0::INVALID end_linsid=0::INVALID }
2024-10-12T00:09:39.969852-05:00 <3.6> CLUSTER-26(id26) isi_job_d[12284]: Worker 13 Stopped: (task_state_clean, 614) FlexProtectLin[6894].0: Discarding unsent task result: { task_result={ jtid=FlexProtectLin jid=6894 phase=0 tid=28-1 rid=58255 ready=false errors=[] } data={ lins=0 files=0 dirs=0 blocks=0 lins_processed=0 sins=0 sins_processed=0 } start_linsid=0::INVALID end_linsid=0::INVALID }
2024-10-12T00:39:46.999158-05:00 <3.6> CLUSTER-2(id2) isi_job_d[78458]: Worker 485 Stopped: (task_state_clean, 614) FlexProtectLin[6894].0: Discarding unsent task result: { task_result={ jtid=FlexProtectLin jid=6894 phase=0 tid=28-1 rid=58365 ready=false errors=[] } data={ lins=0 files=0 dirs=0 blocks=0 lins_processed=0 sins=0 sins_processed=0 } start_linsid=0::INVALID end_linsid=0::INVALID }
2024-10-12T01:18:53.867843-05:00 <3.6> CLUSTER-11(id11) isi_job_d[28510]: Worker 53 Stopped: (task_state_clean, 614) FlexProtectLin[6894].0: Discarding unsent task result: { task_result={ jtid=FlexProtectLin jid=6894 phase=0 tid=28-1 rid=60666 ready=false errors=[] } data={ lins=0 files=0 dirs=0 blocks=0 lins_processed=0 sins=0 sins_processed=0 } start_linsid=0::INVALID end_linsid=0::INVALID }
2024-10-12T02:21:01.143101-05:00 <3.6> CLUSTER-28(id28) isi_job_d[11777]: Worker 18 Stopped: (task_state_clean, 614) FlexProtectLin[6894].0: Discarding unsent task result: { task_result={ jtid=FlexProtectLin jid=6894 phase=0 tid=28-1 rid=58221 ready=false errors=[] } data={ lins=0 files=0 dirs=0 blocks=0 lins_processed=0 sins=0 sins_processed=0 } start_linsid=0::INVALID end_linsid=0::INVALID }
2024-10-12T03:19:07.198836-05:00 <3.6> CLUSTER-1(id1) isi_job_d[87488]: Worker 561 Stopped: (task_state_clean, 614) FlexProtectLin[6894].0: Discarding unsent task result: { task_result={ jtid=FlexProtectLin jid=6894 phase=0 tid=28-1 rid=60128 ready=false errors=[] } data={ lins=0 files=0 dirs=0 blocks=0 lins_processed=0 sins=0 sins_processed=0 } start_linsid=0::INVALID end_linsid=0::INVALID }
The below commands can be used to confirm the current number of tasks, and what they are working on:
for i in $(isi job list|grep '^[0-9].*Running'|awk '{print $1}'); do isi job view $i; isi job statistics view -v --job-id=$i|grep -o 'Workers: [0-9]*'|sort |uniq -c; echo $(find /ifs/.ifsvar/modules/jobengine/cp/$i/tasks -type f | wc -l) tasks remaining; done;
Replace JOBID with the JobID number for the job in question:--
isi_for_array -XQ 'for n in $(sysctl efs.bam.busy_vnodes | grep "pid $(pgrep -f JOBID)" | egrep -o "[[:alnum:]]{1,4}:[[:alnum:]]{1,4}:[[:alnum:]]{1,4}"|sort|uniq); do isi get -L "$n" 2>&1; done' | grep -v 'job_d\|modules/jobengine' | sort | uniq -c
Resolution
If confirmed that the job is going waiting or running frequently due to other jobs starting, then temporarily modify to a higher priority.
A priority of 2 can be used to prevent jobs from interrupting the job of concern and can be returned to default once the job completes.
Contact support for assistance and reference this KB article if the job appears to throttle the workers causing the task to be discarded multiple times.