search

FCP-INDI / cpac_run_logs

Repository for information about C-PAC runs.
1 stars 1 forks source link

C-PAC v1.8.1.dev@2151079 #18

Closed shnizzedy closed 2 years ago

shnizzedy commented 3 years ago

C-PAC Run Info
Description ":flushed: I see my recent run died with Disk quota exceeded" (Columbia test run) on AWS
Version https://github.com/FCP-INDI/C-PAC/commit/2151079999487986108289d2cb9a15a7af9c928e
Container Docker

Client:
 Version:           18.09.7
 API version:       1.39
 Go version:        go1.10.4
 Git commit:        2d0083d
 Built:             Wed Oct 14 19:42:56 2020
 OS/Arch:           linux/amd64
 Experimental:      false

Server:
 Engine:
  Version:          18.09.7
  API version:      1.39 (minimum version 1.12)
  Go version:       go1.10.4
  Git commit:       2d0083d
  Built:            Wed Oct 14 17:25:58 2020
  OS/Arch:          linux/amd64
  Experimental:     false
System AWS
Data Size 
anat: 256 × 320 × 320
func: 90 × 104 × 72 × 1200
      RepetitionTime: 0.72
Results crash-20210410-235930-root-frequency_filter.a5-0783f355-955a-47e4-8b0a-6bc1ab554872.txt
Node: cpac_sub-105923_ses-retest.filtering_bold_and_regressors_Regressor-3_241.frequency_filter
Working directory: /outputs/working/cpac_sub-105923_ses-retest/filtering_bold_and_regressors_Regressor-3_241/_scan_restLRpredrvt_run-2/frequency_filter

Node inputs:

bandpass_freqs = [0.01, 0.1]
function_str = CPAC.nuisance.bandpass.bandpass_voxels
realigned_file = 
regressor_file = 
sample_period = 

Traceback (most recent call last):
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 67, in run_node
    result["result"] = node.run(updatehash=updatehash)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 516, in run
    result = self._run_interface(execute=True)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 635, in _run_interface
    return self._run_command(execute)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 741, in _run_command
    result = self._interface.run(cwd=outdir)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/interfaces/base/core.py", line 419, in run
    runtime = self._run_interface(runtime)
  File "/code/CPAC/utils/interfaces/function.py", line 152, in _run_interface
    out = function_handle(args)
  File "/code/CPAC/nuisance/bandpass.py", line 69, in bandpass_voxels
    mask = (data != 0).sum(-1) != 0
AttributeError: 'bool' object has no attribute 'sum'

crash-20210411-000521-root-frequency_filter.a5-a49202d1-bf78-443c-9810-7ac3981702a3.txt
Node: cpac_sub-105923_ses-retest.filtering_bold_and_regressors_Regressor-3_257.frequency_filter
Working directory: /outputs/working/cpac_sub-105923_ses-retest/filtering_bold_and_regressors_Regressor-3_257/_scan_restLRpredrvt_run-2/frequency_filter

Node inputs:

bandpass_freqs = [0.01, 0.1]
function_str = CPAC.nuisance.bandpass.bandpass_voxels
realigned_file = 
regressor_file = 
sample_period = 

Traceback (most recent call last):
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 67, in run_node
    result["result"] = node.run(updatehash=updatehash)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 516, in run
    result = self._run_interface(execute=True)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 635, in _run_interface
    return self._run_command(execute)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 741, in _run_command
    result = self._interface.run(cwd=outdir)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/interfaces/base/core.py", line 419, in run
    runtime = self._run_interface(runtime)
  File "/code/CPAC/utils/interfaces/function.py", line 152, in _run_interface
    out = function_handle(args)
  File "/code/CPAC/nuisance/bandpass.py", line 68, in bandpass_voxels
    data = nii.get_data().astype('float64')
MemoryError

Include:

 
OUTPUT=${CN}/CPAC_Out_2
mkdir -p ${OUTPUT}
#chmod -R 777 $output
docker run \
-v ${CN}/bids_dataset:/bids_dataset \
-v /${OUTPUT}:/outputs \
-v /media/ebs/C-PAC:/code \
-v /tmp:/scratch -v ${CN}/configs:/configs \
fcpindi/c-pac:nightly /bids_dataset /outputs participant \
--pipeline_file /configs/prelim_forks_ses_retest.yml \
--save_working_dir \
--n_cpus 6 \
--mem_gb 100 \
--pipeline_override "pipeline_setup: {system_config: {max_cores_per_participant: 6, maximum_memory_per_participant: 20, num_ants_threads: 6}}" \
--participant_label 105923

:paperclip: prelim_forks_ses_retest.yml

BIDS directory / --participant_label 105923

Developers only:
cpac_pipeline_config_2021-04-10T15-59-39Z_min.yml
shnizzedy commented 3 years ago

Could be a threading issue. Runnning the function working/cpac_sub-105923_ses-retest/filtering_bold_and_regressors_Regressor-3_241/_scan_restLRpredrvt_run-2/frequency_filter/_report/report.rst

Node: filtering_bold_and_regressors_Regressor-3_241 (frequency_filter (interfaces)

Hierarchy : cpac_sub-105923_ses-retest.filtering_bold_and_regressors_Regressor-3_241.frequency_filter Exec ID : frequency_filter.a5

Original Inputs

  • bandpass_freqs : [0.01, 0.1]
  • function_str : CPAC.nuisance.bandpass.bandpass_voxels
  • realigned_file : /outputs/working/cpac_sub-105923_ses-retest/nuisance_regression_Regressor-3_241/_scan_restLRpredrvt_run-2/nuisance_regression/residuals.nii.gz
  • regressor_file : /outputs/working/cpac_sub-105923_ses-retest/nuisance_regressors_Regressor-3_241/_scan_restLRpredrvt_run-2/build_nuisance_regressors/nuisance_regressors.1D
  • sample_period : <undefined>

directly works fine:

>>> bandpass_voxels(realigned_file, regressor_file, bpfs)                                                                                                                            
/media/ebs/C-PAC/CPAC/nuisance/bandpass.py:82: ComplexWarning: Casting complex values to real discards the imaginary part
  Y_bp[:, j] = ideal_bandpass(Yc[:, j], sample_period, bandpass_freqs) 
('/media/ebs/C-PAC/bandpassed_demeaned_filtered.nii.gz',
 '/media/ebs/C-PAC/regressor_bandpassed_demeaned_filtered.1D')
shnizzedy commented 3 years ago

Rerunning without threading worked :partying_face: :

210416-09:05:41,195 nipype.workflow INFO:

    End of subject workflow cpac_sub-NDARAA504CRN_1   

    CPAC run complete:

        Pipeline configuration: cpac_fmriprep-96-forks
        Subject workflow: cpac_sub-NDARAA504CRN_1
        Elapsed run time (minutes): 1104.4941056927046
        Timing information saved in /outputs/log/cpac_individual_timing_cpac_fmriprep-96-forks.csv
        System time of start:      2021-04-15 14:41:19
        System time of completion: 2021-04-16 09:05:41

(different subject, smaller image (anat: 176 × 256 × 256; func: 84 × 84 × 60 × 250, RepetitionTime: 0.8), took 18.5 hours for one subject)

With threading, segfault:

210415-21:25:00,592 nipype.workflow INFO:
         [MultiProc] Running 3 tasks, and 65 jobs ready. Free memory (GB): 62.50/100.00, Free processors: 0/3.   
                     Currently running:
                       * cpac_sub-NDARAA504CRN_1.nuisance_regressors_Regressor-2_243.aCompCor_DetrendPC
                       * cpac_sub-NDARAA504CRN_1.nuisance_regressors_Regressor-5_243.aCompCor_DetrendPC
                       * cpac_sub-NDARAA504CRN_1.nuisance_regressors_Regressor-6_243.aCompCor_DetrendPC
Fatal Python error: Segmentation fault

Thread 0x00007fc11fdb3700 (most recent call first):
  File "/usr/local/miniconda/lib/python3.7/threading.py", line 300 in wait
  File "/usr/local/miniconda/lib/python3.7/threading.py", line 552 in wait
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/utils/profiler.py", line 107 in run
  File "/usr/local/miniconda/lib/python3.7/threading.py", line 926 in _bootstrap_inner
  File "/usr/local/miniconda/lib/python3.7/threading.py", line 890 in _bootstrap

Current thread 0x00007fc139b66740 (most recent call first):
  File "/usr/local/miniconda/lib/python3.7/site-packages/numpy/core/_methods.py", line 121 in _var
  File "/usr/local/miniconda/lib/python3.7/site-packages/numpy/core/_methods.py", line 140 in _std
  File "<string>", line 29 in calc_compcor_components
  File "/code/CPAC/utils/interfaces/function.py", line 152 in _run_interface
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/interfaces/base/core.py", line 419 in run
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 741 in _run_command
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 635 in _run_interface
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 516 in run
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 67 in run_node
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/process.py", line 239 in _process_worker
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/process.py", line 99 in run
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/process.py", line 297 in _bootstrap
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/popen_fork.py", line 74 in _launch
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/popen_fork.py", line 20 in __init__
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/context.py", line 277 in _Popen
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/process.py", line 112 in start
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/process.py", line 607 in _adjust_process_count
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/process.py", line 583 in _start_queue_management_thread
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/process.py", line 641 in submit
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 175 in _submit_job
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 367 in _send_procs_to_workers
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/base.py", line 184 in run
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/workflows.py", line 632 in run   
  File "/code/CPAC/pipeline/cpac_pipeline.py", line 450 in run_workflow
  File "/code/CPAC/pipeline/cpac_runner.py", line 549 in run
  File "/code/run.py", line 677 in <module>
exception calling callback for <Future at 0x7fc06aab6ed0 state=finished raised BrokenProcessPool>
Traceback (most recent call last):
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
concurrent.futures.process.BrokenProcessPool: A process in the process pool was terminated abruptly while the future was running or pending.
exception calling callback for <Future at 0x7fc06aafbd50 state=finished raised BrokenProcessPool>
Traceback (most recent call last):
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
concurrent.futures.process.BrokenProcessPool: A process in the process pool was terminated abruptly while the future was running or pending.
exception calling callback for <Future at 0x7fc06aa8ef90 state=finished raised BrokenProcessPool>
Traceback (most recent call last):
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
concurrent.futures.process.BrokenProcessPool: A process in the process pool was terminated abruptly while the future was running or pending.
shnizzedy commented 3 years ago

Quite a few nodes used more resources than estimated in the successful run. Most were close, but I'm guessing the issue is that the small overruns add up with the multitude of forks.

I'm going to try increasing the estimates for each of those nodes to accommodate as a stopgap until https://github.com/FCP-INDI/C-PAC/issues/1480 is resolved; I'll retry threading with the increased estimates.

shnizzedy commented 3 years ago

The successful run also included this warning sequence 9 times after the CPAC run complete message:

/code/CPAC/nuisance/bandpass.py:82: ComplexWarning: Casting complex values to real discards the imaginary part
  Y_bp[:, j] = ideal_bandpass(Yc[:, j], sample_period, bandpass_freqs)
/usr/local/miniconda/lib/python3.7/site-packages/numpy/lib/function_base.py:2530: RuntimeWarning: divide by zero encountered in true_divide
  c /= stddev[:, None]
/usr/local/miniconda/lib/python3.7/site-packages/numpy/lib/function_base.py:2530: RuntimeWarning: invalid value encountered in true_divide
  c /= stddev[:, None]
/usr/local/miniconda/lib/python3.7/site-packages/numpy/lib/function_base.py:2531: RuntimeWarning: divide by zero encountered in true_divide
  c /= stddev[None, :]
/usr/local/miniconda/lib/python3.7/site-packages/numpy/lib/function_base.py:2531: RuntimeWarning: invalid value encountered in true_divide
  c /= stddev[None, :]
shnizzedy commented 3 years ago

Good news: https://github.com/FCP-INDI/C-PAC/pull/1499 seems to be working!

Bad news: https://github.com/FCP-INDI/C-PAC/issues/1480 / https://github.com/FCP-INDI/C-PAC/pull/1499 doesn't seem to resolve the issue here:

210428-16:20:01,710 nipype.workflow INFO:
         [Node] Setting-up "cpac_sub-105923_ses-retest.nuisance_regressors_Regressor-5_241.CerebrospinalFluid_2mm_Ventricles" in "/outputs/working_ses_test/cpac_sub-105923_ses-retest/nuisance_regressors_
Regressor-5_241/CerebrospinalFluid_2mm_Ventricles".
210428-16:20:01,716 nipype.workflow INFO:
         [Node] Running "CerebrospinalFluid_2mm_Ventricles" ("nipype.interfaces.afni.utils.Calc"), a CommandLine Interface with command:
3dcalc -a /outputs/working_ses_test/cpac_sub-105923_ses-retest/nuisance_regressors_Regressor-5_241/VentriclesToAnat_2mm_ants/HarvardOxford-lateral-ventricles-thr25-2mm_trans.nii.gz -b /outputs/working_se
s_test/cpac_sub-105923_ses-retest/nuisance_regressors_Regressor-5_241/CerebrospinalFluid_2mm_flirt/segment_tissue_mask_flirt.nii.gz -expr "a*b" -prefix csf_lat_ven_mask.nii.gz
210428-16:20:02,706 nipype.workflow INFO:
         [Node] Finished "cpac_sub-105923_ses-retest.nuisance_regressors_Regressor-5_241.CerebrospinalFluid_2mm_Ventricles".
210428-16:20:03,55 nipype.workflow INFO:
         [Job 9282] Completed (cpac_sub-105923_ses-retest.nuisance_regressors_Regressor-5_241.CerebrospinalFluid_2mm_Ventricles).
210428-16:20:03,100 nipype.workflow INFO:
         [MultiProc] Running 3 tasks, and 79 jobs ready. Free memory (GB): 93.10/100.00, Free processors: 1/4.
                     Currently running:
                       * cpac_sub-105923_ses-retest.nuisance_regressors_Regressor-6_241.aCompCor_DetrendPC
                       * _apply_warp_warp_ts_to_T1template_3581
                       * _apply_warp_warp_ts_to_T1template_3580
210428-16:20:03,708 nipype.workflow INFO:
         [Node] Setting-up "cpac_sub-105923_ses-retest.nuisance_regressors_Regressor-5_241.aCompCor_merge_masks" in "/outputs/working_ses_test/cpac_sub-105923_ses-retest/nuisance_regressors_Regressor-5_2
41/aCompCor_merge_masks".
210428-16:20:03,713 nipype.workflow INFO:
         [Node] Running "aCompCor_merge_masks" ("nipype.interfaces.utility.base.Merge")
210428-16:20:03,922 nipype.workflow INFO:
         [Node] Finished "cpac_sub-105923_ses-retest.nuisance_regressors_Regressor-5_241.aCompCor_merge_masks".
210428-16:20:05,81 nipype.workflow INFO:
         [Job 9283] Completed (cpac_sub-105923_ses-retest.nuisance_regressors_Regressor-5_241.aCompCor_merge_masks).
210428-16:20:05,150 nipype.workflow INFO:
         [MultiProc] Running 3 tasks, and 79 jobs ready. Free memory (GB): 93.10/100.00, Free processors: 1/4.
                     Currently running:
                       * cpac_sub-105923_ses-retest.nuisance_regressors_Regressor-6_241.aCompCor_DetrendPC
                       * _apply_warp_warp_ts_to_T1template_3581
                       * _apply_warp_warp_ts_to_T1template_3580
Fatal Python error: Segmentation fault

Thread 0x00007f1f5040f700 (most recent call first):
  File "/usr/local/miniconda/lib/python3.7/threading.py", line 300 in wait
  File "/usr/local/miniconda/lib/python3.7/threading.py", line 552 in wait
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/utils/profiler.py", line 107 in run
  File "/usr/local/miniconda/lib/python3.7/threading.py", line 926 in _bootstrap_inner
  File "/usr/local/miniconda/lib/python3.7/threading.py", line 890 in _bootstrap

Current thread 0x00007f1f6a1c2740 (most recent call first):
  File "/usr/local/miniconda/lib/python3.7/site-packages/numpy/core/_methods.py", line 121 in _var
  File "/usr/local/miniconda/lib/python3.7/site-packages/numpy/core/_methods.py", line 140 in _std
  File "<string>", line 29 in calc_compcor_components
  File "/code/CPAC/utils/interfaces/function.py", line 152 in _run_interface
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/interfaces/base/core.py", line 419 in run
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 741 in _run_command
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 635 in _run_interface
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/nodes.py", line 516 in run
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 67 in run_node
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/process.py", line 239 in _process_worker
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/process.py", line 99 in run
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/process.py", line 297 in _bootstrap
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/popen_fork.py", line 74 in _launch
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/popen_fork.py", line 20 in __init__
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/context.py", line 277 in _Popen
  File "/usr/local/miniconda/lib/python3.7/multiprocessing/process.py", line 112 in start
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/process.py", line 607 in _adjust_process_count
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/process.py", line 583 in _start_queue_management_thread
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/process.py", line 641 in submit
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 175 in _submit_job
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 367 in _send_procs_to_workers
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/base.py", line 184 in run
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/workflows.py", line 632 in run
  File "/code/CPAC/pipeline/cpac_pipeline.py", line 450 in run_workflow
  File "/code/CPAC/pipeline/cpac_runner.py", line 556 in run
  File "/code/run.py", line 677 in <module>
210428-16:20:05,898 nipype.workflow INFO:
         [Node] Setting-up "cpac_sub-105923_ses-retest.nuisance_regressors_Regressor-5_241.aCompCor_union_masks" in "/outputs/working_ses_test/cpac_sub-105923_ses-retest/nuisance_regressors_Regressor-5_241/aCompCor_union_masks".
210428-16:20:05,904 nipype.workflow INFO:
         [Node] Running "aCompCor_union_masks" ("CPAC.utils.interfaces.masktool.MaskTool"), a CommandLine Interface with command:
3dmask_tool -prefix csf_lat_ven_mask_mask.nii.gz -input /outputs/working_ses_test/cpac_sub-105923_ses-retest/nuisance_regressors_Regressor-5_241/aCompCor_union_masks/csf_lat_ven_mask.nii.gz /outputs/working_ses_test/cpac_sub-105923_ses-retest/nuisance_regressors_Regressor-5_241/aCompCor_union_masks/segment_tissue_mask_flirt.nii.gz
exception calling callback for <Future at 0x7f1e9b599f10 state=finished raised BrokenProcessPool>
Traceback (most recent call last):
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
concurrent.futures.process.BrokenProcessPool: A process in the process pool was terminated abruptly while the future was running or pending.
exception calling callback for <Future at 0x7f1ea2f61b90 state=finished raised BrokenProcessPool>
Traceback (most recent call last):
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
concurrent.futures.process.BrokenProcessPool: A process in the process pool was terminated abruptly while the future was running or pending.
exception calling callback for <Future at 0x7f1e9b68fb50 state=finished raised BrokenProcessPool>
Traceback (most recent call last):
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
concurrent.futures.process.BrokenProcessPool: A process in the process pool was terminated abruptly while the future was running or pending.
exception calling callback for <Future at 0x7f1e9b797290 state=finished raised BrokenProcessPool>
Traceback (most recent call last):
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 324, in _invoke_callbacks
    callback(self)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/multiproc.py", line 159, in _async_callback
    result = args.result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 428, in result
    return self.__get_result()
  File "/usr/local/miniconda/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
concurrent.futures.process.BrokenProcessPool: A process in the process pool was terminated abruptly while the future was running or pending.
210428-16:20:07,116 nipype.workflow INFO:
         [MultiProc] Running 4 tasks, and 78 jobs ready. Free memory (GB): 89.50/100.00, Free processors: 0/4.
                     Currently running:
                       * cpac_sub-105923_ses-retest.nuisance_regressors_Regressor-5_241.aCompCor_union_masks
                       * cpac_sub-105923_ses-retest.nuisance_regressors_Regressor-6_241.aCompCor_DetrendPC
                       * _apply_warp_warp_ts_to_T1template_3581
                       * _apply_warp_warp_ts_to_T1template_3580
shnizzedy commented 3 years ago

:partying_face: (300 TRs)

docker run \
-v /$output:/outputs \
-v ${BIDS_DIR}:/bids_dataset \
-v ${DATA_CONFIG}:/data_config \
-v ${CPAC_DIR}:/code \
-v ${CPAC_DIR}/CPAC/resources/configs:${CPAC_DIR}/CPAC/resources/configs \
-v /tmp:/scratch -v /media/ebs/Columbia_Nim/configs:/configs \
fcpindi/c-pac:nightly /bids_dataset /outputs participant \
--data_config_file /data_config/300.yml \
--pipeline_file /configs/prelim_forks_ses_test.yml \
--mem_gb 100 \
--participant_label 105923 \
--n_cpus 4 \
--pipeline_override "pipeline_setup: {system_config: {max_cores_per_participant: 4, maximum_memory_per_participant: 50, num_ants_threads: 4}}"
210505-23:58:04,637 nipype.workflow INFO:

    End of subject workflow cpac_sub-105923_ses-retest

    CPAC run complete:

        Pipeline configuration: cpac_fmriprep-96-forks
        Subject workflow: cpac_sub-105923_ses-retest
        Elapsed run time (minutes): 301.94692585468295
        Timing information saved in /outputs/log/cpac_individual_timing_cpac_fmriprep-96-forks.csv
        System time of start:      2021-05-05 19:00:24
        System time of completion: 2021-05-05 23:58:04

:sob: (1200 TRs)

docker run \
-v /$output:/outputs \
-v ${BIDS_DIR}:/bids_dataset \
-v ${CPAC_DIR}:/code \
-v ${DATA_CONFIG}:/data_config \
-v ${CPAC_DIR}/CPAC/resources/configs:${CPAC_DIR}/CPAC/resources/configs \
-v /tmp:/scratch -v /media/ebs/Columbia_Nim/configs:/configs \
fcpindi/c-pac:nightly /bids_dataset /outputs participant \
--data_config_file /data_config/1200.yml \
--pipeline_file /configs/prelim_forks_ses_test.yml \
--mem_gb 100 \
--participant_label 105923 \
--n_cpus 4 \
--pipeline_override "pipeline_setup: {system_config: {max_cores_per_participant: 4, maximum_memory_per_participant: 50, num_ants_threads: 4}}"
Error of subject workflow cpac_sub-105923_ses-retest

CPAC run error:

    Pipeline configuration: cpac_fmriprep-96-forks
    Subject workflow: cpac_sub-105923_ses-retest
    Elapsed run time (minutes): 101.04634671211242
    Timing information saved in /outputs/log/cpac_individual_timing_cpac_fmriprep-96-forks.csv
    System time of start:      2021-05-05 21:51:51

210505-23:28:43,14 nipype.workflow INFO:
         Removing working dir: /outputs/working_ses_test/cpac_sub-105923_ses-retest
210505-23:28:49,564 nipype.workflow WARNING:
         Storing result file without outputs
210505-23:28:49,564 nipype.workflow WARNING:
         [Node] Error on "cpac_sub-105923_ses-retest.func_concat_77" (/outputs/working_ses_test/cpac_sub-105923_ses-retest/_scan_restLR_run-1/func_concat_77)
210505-23:28:49,564 nipype.workflow WARNING:
         Interface finished unexpectedly and the corresponding unfinished hashfile /outputs/working_ses_test/cpac_sub-105923_ses-retest/_scan_restLR_run-1/func_concat_77/_0xb4f67a7a71ecddbc6cd673ad47ca4563_unfinished.json does not exist. Another nipype instance may be running against the same work directory. Please ensure no other concurrent workflows are racing
Traceback (most recent call last):
  File "/code/CPAC/pipeline/cpac_pipeline.py", line 450, in run_workflow
    workflow.run(plugin=plugin, plugin_args=plugin_args)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/engine/workflows.py", line 632, in run
    runner.run(execgraph, updatehash=updatehash, config=self.config)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/base.py", line 184, in run
    self._send_procs_to_workers(updatehash=updatehash, graph=graph)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/legacymultiproc.py", line 440, in _send_procs_to_workers
    self._task_finished_cb(jobid)
  File "/usr/local/miniconda/lib/python3.7/site-packages/nipype/pipeline/plugins/base.py", line 406, in _task_finished_cb
    self._status_callback(self.procs[jobid], "end")
  File "/code/CPAC/utils/monitoring/monitoring.py", line 73, in log_nodes_cb
    'estimated_memory_gb': node.mem_gb,
  File "/code/CPAC/pipeline/nipype_pipeline_engine/engine.py", line 102, in mem_gb
    return self._apply_mem_x(mem_x_path)
  File "/code/CPAC/pipeline/nipype_pipeline_engine/engine.py", line 126, in _apply_mem_x
    if os.path.exists(mem_x_path):
  File "/usr/local/miniconda/lib/python3.7/genericpath.py", line 19, in exists
    os.stat(path)
TypeError: stat: path should be string, bytes, os.PathLike or integer, not TraitListObject
/code/CPAC/utils/monitoring/draw_gantt_chart.py:64: Warning: 'Event logged twice or events started at exact same time!'
shnizzedy commented 3 years ago

Success now with 600 TRs:

    End of subject workflow cpac_sub-105923_ses-retest

    CPAC run complete:

        Pipeline configuration: cpac_fmriprep-96-forks
        Subject workflow: cpac_sub-105923_ses-retest
        Elapsed run time (minutes): 435.1852345665296
        Timing information saved in /outputs/log/cpac_individual_timing_cpac_fmriprep-96-forks.csv
        System time of start:      2021-05-07 13:21:04
        System time of completion: 2021-05-07 20:31:50