search

bbfrederick / rapidtide

rapidtide - a suite of programs for doing time lag correlation analysis on fMRI data
Apache License 2.0
75 stars 14 forks source link

[REF] Use logging instead of printed statements #65

Closed tsalo closed 3 years ago

tsalo commented 3 years ago

Closes #41.

To do:

Changes proposed in this pull request:

bbfrederick commented 3 years ago

I'm not sure why this is failing tests - it seems to be internal to CircleCI, not due to any code changes.

bbfrederick commented 3 years ago

I got really bogged down working on PICAchooser this weekend - came back to finish accepting this, and the PR seems to have been closed without being accepted. Did you pull it?

bbfrederick commented 3 years ago

Uh oh - something seems a bit wonky. Logging is throwing a lot of errors on the test run (but completing). Command follows:

rapidtide \
        sub-RAPIDTIDETEST.nii.gz \
        ../dst/sub-RAPIDTIDETEST \
        --spatialfilt 2 \
        --nprocs -1 \
        --passes 3

Results below:

memprofiler does not exist
no aggressive optimization
will not use numba even if present
INFO:rapidtide.workflows.utils:Removing existing file: ../dst/sub-RAPIDTIDETEST_log.txt
INFO:rapidtide.workflows.utils:Removing existing file: ../dst/sub-RAPIDTIDETEST_runtimings.tsv
INFO:rapidtide.workflows.utils:Removing existing file: ../dst/sub-RAPIDTIDETEST_memusage.tsv
INFO:rapidtide.workflows.rapidtide:setting internal precision to double
setting internal precision to double
INFO:rapidtide.workflows.rapidtide:setting output precision to single
setting output precision to single
INFO:rapidtide.workflows.rapidtide:input file is NIFTI
input file is NIFTI
INFO:rapidtide.workflows.rapidtide:oversample factor set to 3
oversample factor set to 3
VERBOSE:rapidtide.workflows.rapidtide:fmri data: 260 timepoints, tr = 1.5, oversamptr = 0.5
fmri data: 260 timepoints, tr = 1.5, oversamptr = 0.5
INFO:rapidtide.workflows.rapidtide:118784 spatial locations, 260 timepoints
118784 spatial locations, 260 timepoints
startpoint set to minimum, (0)
endppoint set to maximum, ( 259 )
INFO:rapidtide.workflows.rapidtide:applying gaussian spatial filter to timepoints 0 to 259 with sigma=2.0
applying gaussian spatial filter to timepoints 0 to 259 with sigma=2.0
Percent complete: [############################################################] 100.00%INFO:rapidtide.workflows.rapidtide:constructing correlation mask
constructing correlation mask
INFO:rapidtide.workflows.rapidtide:generating correlation mask from mean image
generating correlation mask from mean image
VERBOSE:rapidtide.workflows.rapidtide:image threshval = 457.48497867212683
image threshval = 457.48497867212683
--- Logging error ---
Traceback (most recent call last):
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 1025, in emit
    msg = self.format(record)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 869, in format
    return fmt.format(record)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 608, in format
    record.message = record.getMessage()
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 369, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/bin/rapidtide", line 4, in <module>
    __import__('pkg_resources').run_script('rapidtide==2.0a20+35.g0291c5fa', 'rapidtide')
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/pkg_resources/__init__.py", line 665, in run_script
    self.require(requires)[0].run_script(script_name, ns)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/pkg_resources/__init__.py", line 1463, in run_script
    exec(code, namespace, namespace)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/rapidtide-2.0a20+35.g0291c5fa-py3.7.egg/EGG-INFO/scripts/rapidtide", line 23, in <module>
    rapidtide_workflow.rapidtide_main(rapidtide_parser.process_args)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/rapidtide-2.0a20+35.g0291c5fa-py3.7.egg/rapidtide/workflows/rapidtide.py", line 667, in rapidtide_main
    LGR.info("validvoxels shape =", numvalidspatiallocs)
Message: 'validvoxels shape ='
Arguments: (26253,)
--- Logging error ---
Traceback (most recent call last):
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 1025, in emit
    msg = self.format(record)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 869, in format
    return fmt.format(record)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 608, in format
    record.message = record.getMessage()
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 369, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/bin/rapidtide", line 4, in <module>
    __import__('pkg_resources').run_script('rapidtide==2.0a20+35.g0291c5fa', 'rapidtide')
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/pkg_resources/__init__.py", line 665, in run_script
    self.require(requires)[0].run_script(script_name, ns)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/pkg_resources/__init__.py", line 1463, in run_script
    exec(code, namespace, namespace)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/rapidtide-2.0a20+35.g0291c5fa-py3.7.egg/EGG-INFO/scripts/rapidtide", line 23, in <module>
    rapidtide_workflow.rapidtide_main(rapidtide_parser.process_args)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/rapidtide-2.0a20+35.g0291c5fa-py3.7.egg/rapidtide/workflows/rapidtide.py", line 667, in rapidtide_main
    LGR.info("validvoxels shape =", numvalidspatiallocs)
Message: 'validvoxels shape ='
Arguments: (26253,)
--- Logging error ---
Traceback (most recent call last):
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 1025, in emit
    msg = self.format(record)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 869, in format
    return fmt.format(record)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 608, in format
    record.message = record.getMessage()
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/logging/__init__.py", line 369, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/bin/rapidtide", line 4, in <module>
    __import__('pkg_resources').run_script('rapidtide==2.0a20+35.g0291c5fa', 'rapidtide')
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/pkg_resources/__init__.py", line 665, in run_script
    self.require(requires)[0].run_script(script_name, ns)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/pkg_resources/__init__.py", line 1463, in run_script
    exec(code, namespace, namespace)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/rapidtide-2.0a20+35.g0291c5fa-py3.7.egg/EGG-INFO/scripts/rapidtide", line 23, in <module>
    rapidtide_workflow.rapidtide_main(rapidtide_parser.process_args)
  File "/Users/frederic/opt/anaconda3/envs/rapidtide_dev/lib/python3.7/site-packages/rapidtide-2.0a20+35.g0291c5fa-py3.7.egg/rapidtide/workflows/rapidtide.py", line 667, in rapidtide_main
    LGR.info("validvoxels shape =", numvalidspatiallocs)
Message: 'validvoxels shape ='
Arguments: (26253,)
INFO:rapidtide.workflows.rapidtide:original size = (118784, 260), trimmed size = (26253, 260)
original size = (118784, 260), trimmed size = (26253, 260)
INFO:rapidtide.workflows.rapidtide:moving fmri data to shared memory
moving fmri data to shared memory
INFO:rapidtide.workflows.rapidtide:no regressor file specified - will use the global mean regressor
no regressor file specified - will use the global mean regressor
INFO:rapidtide.workflows.rapidtide:constructing global mean signal using mean
constructing global mean signal using mean
INFO:rapidtide.workflows.rapidtide:Using 1 components, accounting for 99.80% of the variance
Using 1 components, accounting for 99.80% of the variance
INFO:rapidtide.workflows.rapidtide:used 26253 voxels to calculate global mean signal
used 26253 voxels to calculate global mean signal
INFO:rapidtide.workflows.rapidtide:using global mean as probe regressor
using global mean as probe regressor
INFO:rapidtide.workflows.rapidtide:Regressor start time, end time, and step: -0.000, 390.000, 1.500
Regressor start time, end time, and step: -0.000, 390.000, 1.500
VERBOSE:rapidtide.workflows.rapidtide:Input vector
Input vector
VERBOSE:rapidtide.workflows.rapidtide:length: 260
length: 260
VERBOSE:rapidtide.workflows.rapidtide:input freq: 0.6666666666666666
input freq: 0.6666666666666666
VERBOSE:rapidtide.workflows.rapidtide:input start time: 0.000
input start time: 0.000
INFO:rapidtide.workflows.rapidtide:synctime is 0.0
synctime is 0.0
INFO:rapidtide.workflows.rapidtide:total probe regressor offset is 0.0
total probe regressor offset is 0.0
VERBOSE:rapidtide.workflows.rapidtide:there are 260 points in the original regressor
there are 260 points in the original regressor
VERBOSE:rapidtide.workflows.rapidtide:the timepoint spacing is 1.5
the timepoint spacing is 1.5
VERBOSE:rapidtide.workflows.rapidtide:the input timecourse start time is 0.0
the input timecourse start time is 0.0
INFO:rapidtide.workflows.rapidtide:first fMRI point is at 0.0 seconds relative to time origin
first fMRI point is at 0.0 seconds relative to time origin
VERBOSE:rapidtide.workflows.rapidtide:os_fmri_x dim-0 shape: 778
os_fmri_x dim-0 shape: 778
VERBOSE:rapidtide.workflows.rapidtide:initial_fmri_x dim-0 shape: 260
initial_fmri_x dim-0 shape: 260
INFO:rapidtide.workflows.rapidtide:filtering to lfo band
filtering to lfo band
INFO:rapidtide.workflows.rapidtide:778 778 260 260
778 778 260 260
VERBOSE:rapidtide.workflows.rapidtide:corrtr=0.5
corrtr=0.5
VERBOSE:rapidtide.workflows.rapidtide:trimmedcorrscale length: 119
trimmedcorrscale length: 119
VERBOSE:rapidtide.workflows.rapidtide:trimmedmiscale length: 0 120
trimmedmiscale length: 0 120
VERBOSE:rapidtide.workflows.rapidtide:corrorigin at point 780 0.5
corrorigin at point 780 0.5
VERBOSE:rapidtide.workflows.rapidtide:corr range from 721 (-29.0) to 840 (30.5)
corr range from 721 (-29.0) to 840 (30.5)
INFO:rapidtide.workflows.rapidtide:allocating memory for correlation arrays (118784, 119) (26253, 119)
allocating memory for correlation arrays (118784, 119) (26253, 119)
INFO:rapidtide.workflows.rapidtide:setting up fast resampling with padtime = 60.0
setting up fast resampling with padtime = 60.0
VERBOSE:rapidtide.workflows.rapidtide:refine is set to True
refine is set to True
VERBOSE:rapidtide.workflows.rapidtide:edgebufferfrac set to 0.0012828736369467607
edgebufferfrac set to 0.0012828736369467607
INFO:rapidtide.workflows.rapidtide:

*********************

*********************
INFO:rapidtide.workflows.rapidtide:Pass number 1
Pass number 1
INFO:rapidtide.workflows.rapidtide:checking reference regressor autocorrelation properties
checking reference regressor autocorrelation properties
INFO:rapidtide.workflows.rapidtide:searching for sidelobes with amplitude > 0.1 with abs(lag) < 30.0 s
searching for sidelobes with amplitude > 0.1 with abs(lag) < 30.0 s
INFO:rapidtide.workflows.rapidtide:no sidelobes found in range
no sidelobes found in range
INFO:rapidtide.workflows.rapidtide:

Significance estimation, pass 1

Significance estimation, pass 1
VERBOSE:rapidtide.workflows.rapidtide:calling getNullDistributionData with args: 2.0 1.5 780 59 60
calling getNullDistributionData with args: 2.0 1.5 780 59 60
processing 10000 voxels with 15 processes
Percent complete: [############################################################] 100.00%
9895 non-zero correlations out of 10000 (98.95%)
INFO:rapidtide.workflows.rapidtide:setting ampthresh to the p < 0.050 threshhold
setting ampthresh to the p < 0.050 threshhold
Crosscorrelation significance thresholds from data:
    p < 0.050 :  0.372
    p < 0.010 :  0.425
    p < 0.005 :  0.427
    p < 0.001 :  0.471
Crosscorrelation significance thresholds from fit:
    p < 0.050 :  0.367
    p < 0.010 :  0.415
    p < 0.005 :  0.433
    p < 0.001 :  0.471
INFO:rapidtide.workflows.rapidtide:

Correlation calculation, pass 1

Correlation calculation, pass 1
processing 26253 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation performed on 26253 voxels
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Time lag estimation pass 1

Time lag estimation pass 1
processing 26253 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 26105 voxels
    ampfails: 0 
    lowlagfails: 67 
    highlagfails: 69 
    lowwidthfails: 12 
    highwidthfail: 0 
    total initfails: 12 
    total fitfails: 148
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling pass 1

Correlation despeckling pass 1
INFO:rapidtide.workflows.rapidtide: Using despeckle_thresh = 5.000
    Using despeckle_thresh = 5.000
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 1

Correlation despeckling subpass 1
processing 8271 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 6781 voxels
    ampfails: 3 
    lowlagfails: 544 
    highlagfails: 485 
    lowwidthfails: 464 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 1490
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 2

Correlation despeckling subpass 2
processing 2870 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 2244 voxels
    ampfails: 3 
    lowlagfails: 239 
    highlagfails: 166 
    lowwidthfails: 221 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 626
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 3

Correlation despeckling subpass 3
processing 1632 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 1231 voxels
    ampfails: 0 
    lowlagfails: 172 
    highlagfails: 97 
    lowwidthfails: 133 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 401
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 4

Correlation despeckling subpass 4
processing 1137 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 840 voxels
    ampfails: 4 
    lowlagfails: 118 
    highlagfails: 78 
    lowwidthfails: 105 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 297
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

11096 voxels despeckled in 4 passes

11096 voxels despeckled in 4 passes
INFO:rapidtide.workflows.rapidtide:

Regressor refinement, pass 1

Regressor refinement, pass 1
INFO:rapidtide.workflows.rapidtide:offset time set to 0.965, total is 0.965
offset time set to 0.965, total is 0.965
location mask created
processing 1121 voxels with 15 processes
Percent complete: [############################################################] 100.00%
performing pca refinement with pcacomponents set to 0.8
Using  42  components, accounting for  80.48% of the variance
pca/avg correlation =  1.0

Timeshift applied to 1121 voxels, 1121 used for refinement: 
     2239  locationfails 
     22384  ampfails 
     17381  lagfails 
     2241  sigmafails
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:regressor difference at end of pass 1 is 0.970085
regressor difference at end of pass 1 is 0.970085
INFO:rapidtide.workflows.rapidtide:

*********************

*********************
INFO:rapidtide.workflows.rapidtide:Pass number 2
Pass number 2
INFO:rapidtide.workflows.rapidtide:checking reference regressor autocorrelation properties
checking reference regressor autocorrelation properties
INFO:rapidtide.workflows.rapidtide:searching for sidelobes with amplitude > 0.1 with abs(lag) < 30.0 s
searching for sidelobes with amplitude > 0.1 with abs(lag) < 30.0 s
INFO:rapidtide.workflows.rapidtide:no sidelobes found in range
no sidelobes found in range
INFO:rapidtide.workflows.rapidtide:

Significance estimation, pass 2

Significance estimation, pass 2
VERBOSE:rapidtide.workflows.rapidtide:calling getNullDistributionData with args: 2.0 1.5 780 59 60
calling getNullDistributionData with args: 2.0 1.5 780 59 60
processing 10000 voxels with 15 processes
Percent complete: [############################################################] 100.00%
9790 non-zero correlations out of 10000 (97.90%)
INFO:rapidtide.workflows.rapidtide:setting ampthresh to the p < 0.050 threshhold
setting ampthresh to the p < 0.050 threshhold
Crosscorrelation significance thresholds from data:
    p < 0.050 :  0.374
    p < 0.010 :  0.445
    p < 0.005 :  0.479
    p < 0.001 :  0.536
Crosscorrelation significance thresholds from fit:
    p < 0.050 :  0.374
    p < 0.010 :  0.441
    p < 0.005 :  0.467
    p < 0.001 :  0.524
INFO:rapidtide.workflows.rapidtide:

Correlation calculation, pass 2

Correlation calculation, pass 2
processing 26253 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation performed on 26253 voxels
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Time lag estimation pass 2

Time lag estimation pass 2
processing 26253 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 25890 voxels
    ampfails: 0 
    lowlagfails: 78 
    highlagfails: 281 
    lowwidthfails: 4 
    highwidthfail: 0 
    total initfails: 4 
    total fitfails: 363
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling pass 2

Correlation despeckling pass 2
INFO:rapidtide.workflows.rapidtide: Using despeckle_thresh = 5.000
    Using despeckle_thresh = 5.000
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 1

Correlation despeckling subpass 1
processing 3898 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 3352 voxels
    ampfails: 1 
    lowlagfails: 204 
    highlagfails: 197 
    lowwidthfails: 147 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 546
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 2

Correlation despeckling subpass 2
processing 951 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 804 voxels
    ampfails: 1 
    lowlagfails: 72 
    highlagfails: 33 
    lowwidthfails: 43 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 147
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 3

Correlation despeckling subpass 3
processing 492 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 393 voxels
    ampfails: 0 
    lowlagfails: 60 
    highlagfails: 18 
    lowwidthfails: 21 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 99
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 4

Correlation despeckling subpass 4
processing 304 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 242 voxels
    ampfails: 1 
    lowlagfails: 18 
    highlagfails: 18 
    lowwidthfails: 26 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 62
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

4791 voxels despeckled in 4 passes

4791 voxels despeckled in 4 passes
INFO:rapidtide.workflows.rapidtide:

Regressor refinement, pass 2

Regressor refinement, pass 2
INFO:rapidtide.workflows.rapidtide:offset time set to -0.137, total is 0.827
offset time set to -0.137, total is 0.827
location mask created
processing 12883 voxels with 15 processes
Percent complete: [############################################################] 100.00%
performing pca refinement with pcacomponents set to 0.8
Using  34  components, accounting for  80.13% of the variance
pca/avg correlation =  0.9999999999999998

Timeshift applied to 12883 voxels, 12883 used for refinement: 
     1111  locationfails 
     10229  ampfails 
     6362  lagfails 
     1111  sigmafails
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:regressor difference at end of pass 2 is 0.109181
regressor difference at end of pass 2 is 0.109181
INFO:rapidtide.workflows.rapidtide:

*********************

*********************
INFO:rapidtide.workflows.rapidtide:Pass number 3
Pass number 3
INFO:rapidtide.workflows.rapidtide:checking reference regressor autocorrelation properties
checking reference regressor autocorrelation properties
INFO:rapidtide.workflows.rapidtide:searching for sidelobes with amplitude > 0.1 with abs(lag) < 30.0 s
searching for sidelobes with amplitude > 0.1 with abs(lag) < 30.0 s
INFO:rapidtide.workflows.rapidtide:no sidelobes found in range
no sidelobes found in range
INFO:rapidtide.workflows.rapidtide:

Significance estimation, pass 3

Significance estimation, pass 3
VERBOSE:rapidtide.workflows.rapidtide:calling getNullDistributionData with args: 2.0 1.5 780 59 60
calling getNullDistributionData with args: 2.0 1.5 780 59 60
processing 10000 voxels with 15 processes
Percent complete: [############################################################] 100.00%
9685 non-zero correlations out of 10000 (96.85%)
INFO:rapidtide.workflows.rapidtide:setting ampthresh to the p < 0.050 threshhold
setting ampthresh to the p < 0.050 threshhold
Crosscorrelation significance thresholds from data:
    p < 0.050 :  0.373
    p < 0.010 :  0.438
    p < 0.005 :  0.458
    p < 0.001 :  0.554
Crosscorrelation significance thresholds from fit:
    p < 0.050 :  0.378
    p < 0.010 :  0.445
    p < 0.005 :  0.471
    p < 0.001 :  0.528
INFO:rapidtide.workflows.rapidtide:

Correlation calculation, pass 3

Correlation calculation, pass 3
processing 26253 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation performed on 26253 voxels
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Time lag estimation pass 3

Time lag estimation pass 3
processing 26253 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 25977 voxels
    ampfails: 0 
    lowlagfails: 46 
    highlagfails: 230 
    lowwidthfails: 0 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 276
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling pass 3

Correlation despeckling pass 3
INFO:rapidtide.workflows.rapidtide: Using despeckle_thresh = 5.000
    Using despeckle_thresh = 5.000
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 1

Correlation despeckling subpass 1
processing 3445 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 3028 voxels
    ampfails: 0 
    lowlagfails: 150 
    highlagfails: 160 
    lowwidthfails: 109 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 417
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 2

Correlation despeckling subpass 2
processing 846 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 741 voxels
    ampfails: 0 
    lowlagfails: 43 
    highlagfails: 34 
    lowwidthfails: 28 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 105
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 3

Correlation despeckling subpass 3
processing 404 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 340 voxels
    ampfails: 0 
    lowlagfails: 22 
    highlagfails: 17 
    lowwidthfails: 25 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 64
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

Correlation despeckling subpass 4

Correlation despeckling subpass 4
processing 233 voxels with 15 processes
Percent complete: [############################################################] 100.00%

Correlation fitted in 207 voxels
    ampfails: 0 
    lowlagfails: 7 
    highlagfails: 10 
    lowwidthfails: 9 
    highwidthfail: 0 
    total initfails: 0 
    total fitfails: 26
Garbage collector: collected 0 objects.
INFO:rapidtide.workflows.rapidtide:

4316 voxels despeckled in 4 passes

4316 voxels despeckled in 4 passes
INFO:rapidtide.workflows.rapidtide:

GLM filtering

GLM filtering
INFO:rapidtide.workflows.rapidtide:rereading sub-RAPIDTIDETEST.nii.gz for GLM filter, please wait
rereading sub-RAPIDTIDETEST.nii.gz for GLM filter, please wait
INFO:rapidtide.workflows.rapidtide:moving fmri data to shared memory
moving fmri data to shared memory
processing 26253 voxels with 15 processes
Percent complete: [############################################################] 100.00%
INFO:rapidtide.workflows.rapidtide:

INFO:rapidtide.workflows.rapidtide:done
done
Processed on bbf-mbp16-2.local ( v2.0alpha20+35.g0291c5fa, 2021-04-06T20:03:25-0400 )
Clock time  Program time    Duration    Description
20210406T200829      0.00         0.00  Start
20210406T200830      0.96         0.96  Finish reading fmrifile
20210406T200831      1.76         0.80  End 3D smoothing
20210406T200834      5.09         3.33  Start moving fmri_data to shared memory
20210406T200835      6.61         1.52  End moving fmri_data to shared memory
20210406T200836      6.67         0.06  Start of reference prep
20210406T200836      7.15         0.48  End of reference prep
20210406T200837      7.78         0.64  Significance estimation start, pass 1
20210406T200839      9.97         2.19  Significance estimation end, pass 1 (4569.81 repetitions/second)
20210406T200839      9.97         0.00  Correlation calculation start, pass 1
20210406T200843     13.89         3.92  Correlation calculation end, pass 1 (6695.51 voxels/second)
20210406T200843     13.89         0.00  Time lag estimation start, pass 1
20210406T200845     16.57         2.68  Time lag estimation end, pass 1 (9757.32 voxels/second)
20210406T200845     16.57         0.00  Correlation despeckle start, pass 1
20210406T200858     28.85        12.29  Correlation despeckle end, pass 1 (903.15 voxels/second)
20210406T200858     28.85         0.00  Regressor refinement start, pass 1
20210406T200858     29.27         0.41  Regressor refinement end, pass 1 (2707.06 voxels/second)
20210406T200858     29.30         0.03  Significance estimation start, pass 2
20210406T200901     31.67         2.38  Significance estimation end, pass 2 (4208.36 repetitions/second)
20210406T200901     31.67         0.00  Correlation calculation start, pass 2
20210406T200904     35.63         3.96  Correlation calculation end, pass 2 (6636.66 voxels/second)
20210406T200904     35.63         0.00  Time lag estimation start, pass 2
20210406T200908     38.98         3.36  Time lag estimation end, pass 2 (7715.61 voxels/second)
20210406T200908     38.99         0.00  Correlation despeckle start, pass 2
20210406T200913     43.70         4.71  Correlation despeckle end, pass 2 (1016.38 voxels/second)
20210406T200913     43.70         0.00  Regressor refinement start, pass 2
20210406T200915     45.95         2.25  Regressor refinement end, pass 2 (5723.92 voxels/second)
20210406T200915     45.99         0.04  Significance estimation start, pass 3
20210406T200917     48.47         2.48  Significance estimation end, pass 3 (4032.11 repetitions/second)
20210406T200917     48.47         0.00  Correlation calculation start, pass 3
20210406T200922     52.74         4.27  Correlation calculation end, pass 3 (6148.06 voxels/second)
20210406T200922     52.74         0.00  Time lag estimation start, pass 3
20210406T200925     55.87         3.13  Time lag estimation end, pass 3 (8303.85 voxels/second)
20210406T200925     55.87         0.00  Correlation despeckle start, pass 3
20210406T200928     59.31         3.44  Correlation despeckle end, pass 3 (1254.45 voxels/second)
20210406T200928     59.31         0.00  GLM filtering start
20210406T200930     61.16         1.85  Start moving fmri_data to shared memory
20210406T200932     62.77         1.61  End moving fmri_data to shared memory
20210406T200934     65.11         2.34  GLM filtering end (11235.69 voxels/second)
20210406T200934     65.11         0.00  Start saving histograms
20210406T200934     65.12         0.01  Finished saving histograms
20210406T200934     65.13         0.01  Start saving maps
20210406T200937     68.01         2.88  Finished saving maps
20210406T200937     68.01         0.00  Done
tsalo commented 3 years ago

Ah, yeah, that's one I missed when I switched from printing to logging. print can handle multiple parts (e.g., print("a", "b", "c")) but those are treated as different arguments in the logger. I need to replace 

LGR.info("validvoxels shape =", numvalidspatiallocs)

with

LGR.info(f"validvoxels shape = {numvalidspatiallocs}")
bbfrederick commented 3 years ago

Ah ok. That will help inspire me to fully embrace f strings :-).