search

mne-tools / mne-bids-pipeline

Automatically process entire electrophysiological datasets using MNE-Python.
https://mne.tools/mne-bids-pipeline/
BSD 3-Clause "New" or "Revised" License
134 stars 65 forks source link

Logging output is much more verbose when running with n_jobs > 1 vs n_jobs=1 #802

Closed hoechenberger closed 8 months ago

hoechenberger commented 9 months ago

After #799, I still see lots of output when Reports are created – but only if n_jobs > 1. For n_jobs = 1, things are working as expected.

❯ mne_bids_pipeline --config=./bids_pipeline_config.py --n_jobs=1
┌────────┬ Welcome aboard MNE-BIDS-Pipeline! 👋 ──────────────────────────────────────────────────────────────────────────────────────────────────────────────
│16:53:26│ 📝 Using configuration: ./bids_pipeline_config.py
│16:53:26│ ❌ Overriding config.n_jobs = 1
└────────┴ 
┌────────┬ init/_01_init_derivatives_dir ─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
│16:53:26│ ⏳️ Initializing output directories.
└────────┴ done (1s)
┌────────┬ init/_02_find_empty_room ──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
│16:53:26│ ⏩ Skipping, empty-room data only relevant for MEG …
└────────┴ done (1s)
┌────────┬ preprocessing/_01_data_quality ────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
│16:53:26│ ⏳️ sub-005 run-01 Initializing report HDF5 file
│16:53:26│ ⏳️ sub-005 run-01 Adding original raw data to report
│16:53:28│ ⏳️ sub-005 run-01 Adding config and sys info to report
❯ mne_bids_pipeline --config=./bids_pipeline_config.py --n_jobs=8
┌────────┬ Welcome aboard MNE-BIDS-Pipeline! 👋 ──────────────────────────────────────────────────────────────────────────────────────────────────────────────
│16:53:50│ 📝 Using configuration: ./bids_pipeline_config.py
│16:53:50│ ❌ Overriding config.n_jobs = 8
└────────┴ 
┌────────┬ init/_01_init_derivatives_dir ─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
│16:53:50│ ✅ Output directories already exist …
└────────┴ done (1s)
┌────────┬ init/_02_find_empty_room ──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
│16:53:50│ ⏩ Skipping, empty-room data only relevant for MEG …
└────────┴ done (1s)
┌────────┬ preprocessing/_01_data_quality ────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
Embedding : jquery-3.6.0.min.js
Embedding : bootstrap.bundle.min.js
Embedding : bootstrap.min.css
Embedding : bootstrap-table/bootstrap-table.min.js
Embedding : bootstrap-table/bootstrap-table.min.css
Embedding : bootstrap-table/bootstrap-table-copy-rows.min.js
Embedding : bootstrap-table/bootstrap-table-export.min.js
Embedding : bootstrap-table/tableExport.min.js
Embedding : bootstrap-icons/bootstrap-icons.mne.min.css
Embedding : highlightjs/highlight.min.js
Embedding : highlightjs/atom-one-dark-reasonable.min.css
│16:53:51│ ⏳️ sub-005 run-01 Adding original raw data to report
│16:53:53│ ⏳️ sub-005 run-01 Adding config and sys info to report
│16:53:54│ ⏳️ sub-005 run-01 Saving report: /Users/richardhochenberger/Library/CloudStorage/OneDrive-FirmenichSA/Documents/TasIn/data/derivatives/sub-005/eeg/sub-005_task-tasin_report.html
Overwriting existing file.
Saving report to : /Users/richardhochenberger/Library/CloudStorage/OneDrive-FirmenichSA/Documents/TasIn/data/derivatives/sub-005/eeg/sub-005_task-tasin_report.h5
Saving report to : /Users/richardhochenberger/Library/CloudStorage/OneDrive-FirmenichSA/Documents/TasIn/data/derivatives/sub-005/eeg/sub-005_task-tasin_report.html
│16:53:54│ ⏳️ sub-102 run-01 Initializing report HDF5 file
Saving report to : /Users/richardhochenberger/Library/CloudStorage/OneDrive-FirmenichSA/Documents/TasIn/data/derivatives/sub-102/eeg/sub-102_task-tasin_report.h5
Embedding : jquery-3.6.0.min.js
Embedding : bootstrap.bundle.min.js
Embedding : bootstrap.min.css
Embedding : bootstrap-table/bootstrap-table.min.js
Embedding : bootstrap-table/bootstrap-table.min.css
Embedding : bootstrap-table/bootstrap-table-copy-rows.min.js
Embedding : bootstrap-table/bootstrap-table-export.min.js
Embedding : bootstrap-table/tableExport.min.js
Embedding : bootstrap-icons/bootstrap-icons.mne.min.css
Embedding : highlightjs/highlight.min.js
Embedding : highlightjs/atom-one-dark-reasonable.min.css
Embedding : jquery-3.6.0.min.js
Embedding : bootstrap.bundle.min.js
Embedding : bootstrap.min.css
Embedding : bootstrap-table/bootstrap-table.min.js
Embedding : bootstrap-table/bootstrap-table.min.css
Embedding : bootstrap-table/bootstrap-table-copy-rows.min.js
Embedding : bootstrap-table/bootstrap-table-export.min.js
Embedding : bootstrap-table/tableExport.min.js
Embedding : bootstrap-icons/bootstrap-icons.mne.min.css
Embedding : highlightjs/highlight.min.js
Embedding : highlightjs/atom-one-dark-reasonable.min.css
│16:53:54│ ⏳️ sub-102 run-01 Adding original raw data to report
│16:53:54│ ⏳️ sub-005 run-04 Adding original raw data to report
│16:53:54│ ⏳️ sub-005 run-04 Adding config and sys info to report
│16:53:54│ ⏳️ sub-102 run-01 Adding config and sys info to report
│16:53:54│ ⏳️ sub-102 run-01 Saving report: /Users/richardhochenberger/Library/CloudStorage/OneDrive-FirmenichSA/Documents/TasIn/data/derivatives/sub-102/eeg/sub-102_task-tasin_report.html
Overwriting existing file.
Saving report to : /Users/richardhochenberger/Library/CloudStorage/OneDrive-FirmenichSA/Documents/TasIn/data/derivatives/sub-102/eeg/sub-102_task-tasin_report.h5
Saving report to : /Users/richardhochenberger/Library/CloudStorage/OneDrive-FirmenichSA/Documents/TasIn/data/derivatives/sub-102/eeg/sub-102_task-tasin_report.html
Embedding : jquery-3.6.0.min.js
Embedding : bootstrap.bundle.min.js
Embedding : bootstrap.min.css
Embedding : bootstrap-table/bootstrap-table.min.js
Embedding : bootstrap-table/bootstrap-table.min.css
Embedding : bootstrap-table/bootstrap-table-copy-rows.min.js
Embedding : bootstrap-table/bootstrap-table-export.min.js
Embedding : bootstrap-table/tableExport.min.js
Embedding : bootstrap-icons/bootstrap-icons.mne.min.css
Embedding : highlightjs/highlight.min.js
Embedding : highlightjs/atom-one-dark-reasonable.min.css
larsoner commented 9 months ago

Assuming threading is used rather than separate processes and threads share memory (can't remember if these are the case), this is probably a MNE-Python limitation because verbose uses logger.level which is a global state. So in one thread something might set logger.level to INFO and in another it might set it to WARNING and vice-versa.

hoechenberger commented 9 months ago

We set the logger level globally to warning by default in MNE-BIDS-Pipeline, so I'm not sure your hypothesis would hold there… in any case, it's destroying our carefully crafted logging output :(