GNU Parallel --joblog 출력의 타임스탬프 이해

GNU Parallel --joblog 출력의 타임스탬프 이해

GNU 병렬이 시작되었습니까?일괄가능한 한 많은 작업(시작할 작업 수는 -jGNU 병렬 내부 또는/및 옵션 및 지정된 매개변수에 의해 제어됨) 일단 완료되면 다음 작업을 시작합니다.일괄일 등?

문맥

작업(시작 시간, 종료 시간, 실행 시간) 및 GNU Parallel과 관련된 타임스탬프를 더 잘 처리하는 방법을 배우고 싶습니다. 여기 예를 들어, log실제 처리 명령이 실행되기 전에 발생하는 사용자 정의 로그(사용자 정의 함수를 통한 로깅)의 타임스탬프를 항상 GNU Parallel에 전달된 for 루프 내에서 사용할 수 있는지 확인하고 싶습니다 . 명령의 실제 처리 실행 시간을 알려줄 수 있나요?

세부 사항

for 루프에 GNU Parallel과 함께 전달한 --joblog두 가지 명령을 배치했습니다. 첫 번째 명령은 log관심 있는 실제 처리를 수행하는 두 번째 명령 앞에 일부 타임스탬프를 포함한 사용자 정의 명령입니다. 사용자 정의 명령의 타이밍은 log직접적으로 중요하지 않습니다. 이는 또 다른 로깅 명령입니다. 안타깝게도 --joblog이 옵션이 어떻게 작동하는지 모르겠습니다 . 여기에 설명된 대로GNU Parallel --joblog는 for 루프 내 명령의 첫 번째 줄만 기록합니다., 첫 번째 명령만 기록합니다.

내가 가지고 있는 로그를 이해하려고 노력하면서mlr--joblog출력의 처음 세 줄 표시

❯ 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

gdalmerge_and_clean위의 내용은 내가 관심 있는 명령의 실행 시간을 의미하지 않습니다 . 그럼에도 불구하고 실행된 모든 명령(일괄?)의 실행 시간은 GNU Parallel에 전달된 for 루프의 반복 내에 있기 때문에 기록 시작 시간은 기록된 각 줄마다 달라야 한다고 생각합니다. 제 생각에는 그렇지 않은 것 같습니다. GNU Parallel은 처음 읽는 명령의 실행 시간을 매우 정확하게 기록합니다.

연속 레코드 간의 차이 Starttime(아래에 표시된 처음 10개 행)

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

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
..

등등. 평균 델타

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

Delta_mean
0.33402504553451784

이것은 분명히 순서와 관련이 있습니다 log. 주문이 너무 빨랐을 것 같지 않습니다 gdalmerge_and_clean.

그럼에도 불구하고 사용자 정의 명령을 기반으로 log전체 시작 및 종료 타임스탬프를 기반으로 실행 중인 모든 작업의 ​​전체 기간을 계산할 수 있습니다.

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

이것은 매우 유용합니다. 하지만 이 "처리" 중에 실행되는 각 작업에 대해 더 자세히 알고 싶습니다. 그래서 log실제 명령을 실행하기 전에 타임스탬프를 기록하는 명령이 있습니다 gdalmerge_and_clean.

이러한 로그 줄은 다음과 같습니다.

..
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
..

사용mlr기록된 타임스탬프 간의 차이를 다시 계산해 보세요. 뭔가 유용한 것이 있을까요? 0이 아닌 차이점은 서로 다른 순간에 시작된 배치 작업의 타임스탬프와 관련이 있습니다(GNU Parallel을 통해 병렬로 실행되기 때문에 동일한 시작 시간을 가진 작업이 많기 때문에 이것이 유용하다고 생각합니다. 그렇죠?).

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

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

아마도 이러한 차이점은 각 개별 작업이 GNU 병렬 for 루프에서 실행되는 데 어느 정도 시간이 걸리는지 보여줍니다. ?

답변1

GNU Parallel은 사용 가능한 작업 슬롯이 있을 때 작업을 시작합니다. 작업 슬롯 수는 CPU 스레드 수로 지정되며 -j/--jobs기본값은 CPU 스레드 수입니다.

서버에 8개의 CPU 스레드가 있다고 가정합니다.

GNU Parallel을 시작하면 즉시 8개의 작업이 생성됩니다. 작업이 완료되면 정보가 기록되고( 에 --joblog) 새 작업이 생성됩니다.

따라서 모든 작업에 정확히 동일한 시간이 걸리면 GNU Parallel이 작업을 일괄 처리하는 것처럼 보입니다. 그러나 그것은 진실이 아니다. 이렇게 하면 무슨 일이 일어나고 있는지 더 쉽게 이해할 수 있습니다.

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

전반적으로 GNU Parallel을 사용하는 것은 gdalmerge_and_cleanGNU Parallel 사용법을 배우기에는 매우 좋지 않은 방법인 것 같습니다. 대신, 더 간단한 예를 사용하여 배우고 배운 내용을 적용하십시오 gdalmerge_and_clean.

관련 정보