1

Does GNU Parallel start a batch of as many jobs as possible (the number of jobs started being governed by GNU Parallel internals or/and the -j option along with given parameters), and once complete, then start the next batch of jobs and so on?

Context

I want to learn how to better handle timestamps related to jobs (start time, end time and then running time) and GNU Parallel. As an example here, I would like to understand if I can make use of the timestamps in my custom logs, recorded via a custom log function, which come just before executing the actual processing command, always inside a for loop that is passed to GNU Parallel. Can they give me the running time of the actual processing commands?

Details

Inside a for loop, passed then to GNU Parallel along with --joblog, I have put two commands : the first command is a custom log command including some timestamping, just before the second command which does the actual processing of interest. The timing of the custom log command is not of direct interest -- it is yet another logging command. Unfortunately, I was not aware of how the --joblog option works -- as explained here GNU Parallel --joblog logs only first line of commands inside a for loop, it only logs the first command.

Trying to make sense of the logs I have, I use mlr to show the first three lines of a --joblog output

❯ mlr --itsv --oxtab head -n 3 parallel/parallel.job.4437.3.log
Seq        1
Host       :
Starttime  1670106266.417
JobRuntime      0.000
Send       0
Receive    0
Exitval    0
Signal     0
Command    log /scratch/pvgis/job.4437.3/Process_2022_12_02_23_15_50_10m_u_component_of_wind_2008.log Action=Metadata, Map=era5_and_land_10m_u_component_of_wind_2008_band_79_merged_scaled.nc, Hours since=946704, Longname=10 metre U wind component, Units=m s**-1

Seq        2
Host       :
Starttime  1670106266.419
JobRuntime      0.009
Send       0
Receive    0
Exitval    0
Signal     0
Command    log /scratch/pvgis/job.4437.3/Process_2022_12_02_23_15_50_10m_u_component_of_wind_2008.log Action=Metadata, Map=era5_and_land_10m_u_component_of_wind_2008_band_39_merged_scaled.nc, Hours since=946705, Longname=10 metre U wind component, Units=m s**-1

Seq        3
Host       :
Starttime  1670106266.422
JobRuntime      0.012
Send       0
Receive    0
Exitval    0
Signal     0
Command    log /scratch/pvgis/job.4437.3/Process_2022_12_02_23_15_50_10m_u_component_of_wind_2008.log Action=Metadata, Map=era5_and_land_10m_u_component_of_wind_2008_band_28_merged_scaled.nc, Hours since=946706, Longname=10 metre U wind component, Units=m s**-1

The above doesn't refer to the running time of the command gdalmerge_and_clean which I am interested in. Nevertheless, I thought that the logged starting time should differ in-between each logged line as the running time of all commands that are executed (in batches?) in an iteration of a for loop passed to GNU Parallel. I guess this is not the case and GNU Parallel is very precise in what it logs which is exactly the running time of the very command it reads first.

The differences between successive Starttime records (below shown the first 10 lines)

mlr --itsv --opprint step -a delta -f Starttime then rename Starttime_delta,Delta then cut -f Starttime,JobRuntime,Delta parallel/parallel.job.4437.3.log |head

are

Starttime      JobRuntime Delta
1670106266.417      0.000 0
1670106266.419      0.009 0.0019998550415039062
1670106266.422      0.012 0.003000020980834961
1670106266.424      0.014 0.002000093460083008
1670106266.427      0.013 0.003000020980834961
1670106266.434      0.012 0.006999969482421875
1670106266.439      0.021 0.004999876022338867
1670106266.442      0.019 0.003000020980834961
1670106266.446      0.018 0.004000186920166016
..

and so on it goes. The average Delta

mlr --itsv --opprint step -a delta -f Starttime then rename Starttime_delta,Delta then cut -f Starttime,JobRuntime,Delta then stats1 -a mean -f Delta parallel/parallel.job.4437.3.log

is

Delta_mean
0.33402504553451784

which obviously concerns to the log commands. Unlikely the gdalmerge_and_clean commands are so fast.

Nonetheless, from the custom log commands, I can compute the overall duration of all Jobs ran from the overall Start and End timestamps

Action=Processing, Start=2022-12-02 23:15:50
Action=Processing, End=2022-12-04 02:16:43

which is very useful. However, I want to know more about each and every single Job ran during this "Processing". This is why there is a log command to record a timestamp just before executing an actual gdalmerge_and_clean command.

These log lines look like so:

..
size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_210_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_211_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_212_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_213_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_214_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_215_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_216_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_217_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_218_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_219_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_220_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_221_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_222_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_223_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_224_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_225_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_226_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_227_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_228_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_229_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_230_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_231_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:48:15
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_232_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_233_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_234_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_235_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_236_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_237_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_238_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_239_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_240_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_241_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_242_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_243_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_244_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_245_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_246_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_247_merged.nc, Pixel 
size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_248_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_249_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_250_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_251_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_252_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_253_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_254_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:55:45
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_255_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_256_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_257_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_258_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_259_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_260_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_261_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_262_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_263_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_264_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_265_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_266_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_267_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_268_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_269_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_270_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_271_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_272_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_273_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_274_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_275_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_276_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
Action=Merge, Output=era5_and_land_10m_u_component_of_wind_2008_band_277_merged.nc, Pixel size=0.099999998304108 -0.100000000000000, Timestamp=2022-12-02 23:56:02
..

Using mlr to compute the differences, again, between the logged timestamp, maybe there is something useful? The non-zero differences concern then the timestamps of batches of jobs started in different moments (I think this is useful because there are many jobs with the same start time, since they run in parallel via GNU Parallel, right?):

mlr --ocsv grep 'Action=Merge, Output' then clean-whitespace then put '$Seconds = localtime2sec($Timestamp)' then step -a delta -f Seconds then cut -f Timestamp,Seconds,Seconds_delta then cat -n then rename n,Job,Seconds_delta,Delta then filter '$Delta != 0' jobs/Process_2022_12_02_23_15_50_10m_u_component_of_wind_2008.log

are

Job,Timestamp,Seconds,Delta
209,2022-12-02 23:48:15,1670024895,625
232,2022-12-02 23:55:45,1670025345,450
255,2022-12-02 23:56:02,1670025362,17
278,2022-12-02 23:56:19,1670025379,17
291,2022-12-02 23:56:20,1670025380,1
301,2022-12-02 23:56:36,1670025396,16
324,2022-12-02 23:56:56,1670025416,20
347,2022-12-02 23:57:11,1670025431,15
370,2022-12-02 23:57:25,1670025445,14
393,2022-12-02 23:57:38,1670025458,13
..
8570,2022-12-03 21:18:20,1670102300,94
8593,2022-12-03 21:19:48,1670102388,88
8616,2022-12-03 21:21:56,1670102516,128
8639,2022-12-03 21:23:54,1670102634,118
8662,2022-12-03 21:25:42,1670102742,108
8685,2022-12-03 21:26:00,1670102760,18
8708,2022-12-03 21:27:12,1670102832,72
8731,2022-12-03 21:28:24,1670102904,72
8754,2022-12-03 21:29:19,1670102959,55
8777,2022-12-03 21:29:59,1670102999,40

Maybe these differences do tell something about how long it took, more or less, for each individual job ran inside a GNU Parallel-ised for loop. ?

5
  • 1
    I run a simple script with a for loop and two echo whose run custom simple functions and I did get both commands in parallel-job.log. Maybe your issue is related to this: GNU Parallel as job queue -- last commands not executed. Commented Dec 5, 2022 at 21:43
  • Interesting. I changed the order of commands : first actual processing command, then log. I will investigate. Commented Dec 6, 2022 at 21:48
  • @EdgarMagallon If in a for loop there are two command to execute and a "counter", like INDEX=1; for IDX in ITEMS ;do command_1 INDEX && command_2 && INDEX=((INDEX + 1)) ;done |parallel does this eventually mess the use of INDEX here? Commented Dec 7, 2022 at 15:05
  • 1
    It would be something like: echo "command_1 $INDEX && command_2 && INDEX=$((INDEX + 1))" (you need $ in INDEX=$((INDEX + 1)) and command_1 $INDEX). However that's a good observation, I really thought the INDEX would update each loop but it seems that does not work and not sure why. I will have to search about the use of variables in parallel Commented Dec 8, 2022 at 0:01
  • The only way to make use of the variable INDEX should be outside the commands in echo "command ...". Like this: for item in {1..10}; do echo "command_1 INDEX && command_2"; INDEX=$((INDEX + 1)) Commented Dec 8, 2022 at 0:14

1 Answer 1

2

GNU Parallel starts a job when there is a free job slot. The number of job slots is given by -j/--jobs and defaults to the number of CPU threads.

Let us assume your server has 8 CPU threads.

When you start GNU Parallel it will spawn 8 jobs immediately. When a job finishes, the info is logged (in --joblog), and a new job is spawned.

So if all your jobs take exactly the same time, it will seem as if GNU Parallel spawns jobs in batches. But it does not. This should make it easier to see what is going on:

seq 1000 | parallel --lb --joblog my.log 'echo Starting {};sleep {};echo Ending {}'

In general it seems using gdalmerge_and_clean is a really bad way of learning how to use GNU Parallel. Instead use much simpler examples to learn from, and then apply what you have learned to gdalmerge_and_clean.

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .