0

I have a job job that I want to run in parallel 10 times and track how many have finished so far. That's done the construct from this post.

It worked great until I added logging. It interferes with the progress bar by interrupting it, adding the the logged message. The progress bar pops up when it's updated again. In long time running jobs, the progress will be lost in the wast number of messages.

According to this resource the solution is to redirect logging to some TQDM handler using logging_redirect_tqdm method which works great when you don't use parallelism.

This behavior can be reproduced with this piece of code:

import multiprocessing
from time import sleep
from tqdm.auto import tqdm
import logging
from tqdm.contrib.logging import logging_redirect_tqdm

def job(n):
    logging.info(f"{n}: something happened")
    sleep(1)    

logging.basicConfig(level=logging.INFO)
with logging_redirect_tqdm():
    with multiprocessing.Pool(2) as p:
        list(tqdm(p.imap(job, list(range(5))), total=5))

Which produces the output with interrupted progress bar:

INFO:root:0: something happened
INFO:root:1: something happened
  0%|                      | 0/5 [00:00<?, ?it/s]
INFO:root:2: something happened
INFO:root:3: something happened
 20%|██████                | 1/5 [00:01<00:04,  1.00s/it]
INFO:root:4: something happened
100%|██████████████████████| 5/5 [00:03<00:00,  1.66it/s]

I would expect the behavior reproductible with this piece of code

# imports and job method definitions ommited for clarity
with logging_redirect_tqdm():
    for i in tqdm(range(5)):
        job(i)

That in the middle of the run produces

INFO:root:0: something happened                                                                                                                                                                       
INFO:root:1: something happened                                                                                                                                                                       
 20%|█████          | 1/5 [00:01<00:04,  1.00s/it]

And at the end the output looks as follows (notice the progress bar with 20% progress is not there)

INFO:root:0: something happened                                                                                                                                                                       
INFO:root:1: something happened                                                                                                                                                                       
INFO:root:2: something happened                                                                                                                                                                       
INFO:root:3: something happened                                                                                                                                                                       
INFO:root:4: something happened                                                                                                                                                                       
100%|███████████████| 5/5 [00:05<00:00,  1.00s/it]

I suspect that the problem is that the method logging_redirect_tqdm doesn't account for parallelism. I've read this issue suggesting that there should be some locks passed to the logging handler and the progress bar. The I tried to play around with tqdm's own parallel examples here but I was not able to glue together the logging handler and the parallelisms (the actual passing the locks).

Does anybody have experience with this?

JaK
  • 66
  • 1
  • 9
  • I would guess that `logging_redirect_tqdm` set ups some global variables that are not propagated to the worker processes. – Elad Weiss Jul 14 '22 at 12:15

0 Answers0