[REF] Use logging instead of printed statements #65

tsalo · 2021-04-03T18:11:35Z

Closes #41.

To do:

Finish converting timing logger
Add additional fields (variables and voxel counts) to timing logger
Convert general logger's formatter to freeform text
Finish converting memory usage logger
Figure out how to handle memprofile with memory usage logger. I'm still not sure what it's for, but I'll figure it out.
Remove sys.exit statements.

Changes proposed in this pull request:

Replace print statements in rapidtide workflow with logged messages.
Remove verbose and debug if statements. The logger natively handles different levels of messages, although I did have to add a new level for the verbose messages.
Replace timing and memory usage trackers with additional, separate loggers.
Streamline fftpack import. Will need to be propagated across the package.
Use f-strings instead of concatenating strings, when appropriate.

rapidtide/util.py

bbfrederick · 2021-04-06T23:55:03Z

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

bbfrederick

Looks good to me. But why did the PR go away?

bbfrederick · 2021-04-07T00:01:58Z

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 · 2021-04-07T00:12:51Z

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 · 2021-04-07T00:22:10Z

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 · 2021-04-07T00:24:33Z

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

tsalo added 3 commits April 2, 2021 16:51

Use logging.

8bc81ee

Additional cleanup.

30ebffe

Fix some mistakes.

dc290c6

tsalo commented Apr 3, 2021

View reviewed changes

rapidtide/util.py Show resolved Hide resolved

tsalo commented Apr 3, 2021

View reviewed changes

rapidtide/util.py Show resolved Hide resolved

tsalo changed the title ~~[ENH] Use logging instead of printed statements~~ [REF] Use logging instead of printed statements Apr 3, 2021

bbfrederick closed this Apr 6, 2021

bbfrederick reviewed Apr 6, 2021

View reviewed changes

bbfrederick reopened this Apr 7, 2021

bbfrederick marked this pull request as ready for review April 7, 2021 00:02

bbfrederick merged commit 0291c5f into bbfrederick:dev Apr 7, 2021

tsalo mentioned this pull request Apr 7, 2021

[REF] Fix logger call and reformat general logger #66

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[REF] Use logging instead of printed statements #65

[REF] Use logging instead of printed statements #65

tsalo commented Apr 3, 2021 •

edited

Loading

bbfrederick commented Apr 6, 2021

bbfrederick left a comment

bbfrederick commented Apr 7, 2021

bbfrederick commented Apr 7, 2021

tsalo commented Apr 7, 2021

bbfrederick commented Apr 7, 2021

[REF] Use logging instead of printed statements #65

[REF] Use logging instead of printed statements #65

Conversation

tsalo commented Apr 3, 2021 • edited Loading

bbfrederick commented Apr 6, 2021

bbfrederick left a comment

Choose a reason for hiding this comment

bbfrederick commented Apr 7, 2021

bbfrederick commented Apr 7, 2021

tsalo commented Apr 7, 2021

bbfrederick commented Apr 7, 2021

tsalo commented Apr 3, 2021 •

edited

Loading