4

My main goal is to run an external python script (client script) by subprocess in another python script (caller script). The console of the caller script displays all output from the client script except the tqdm output - so it is not a general problem of displaying output by subprocess, but a specific problem related to subprocess interacting with tqdm.

My secondary goal is that I'd like to understand it :). So thoughtful explanations are much appreciated.

The client script (train.py) contains several tqdm calls. So far, I haven't seen much difference in outputs between various tqdm argument configurations, so let's use the simplest one.

In train.py:

...
from tqdm import tqdm

with tqdm(total = 10, ncols = 80,
          file=sys.stdout, position = 0, leave = True,
          desc='f5b: pbar.set_postfix') as pbar:
    for i in range(10):
        pbar.update(1)
        postfix = {'loss': '{0:.4f}'.format(1+i)}
        pbar.set_postfix(**postfix)
        sleep(0.1)

The caller script experiment.py executes the function execute_experiment which calls train.py by the argument command_list:

def execute_experiment(command_list):
    tic = time.time()
    try:
        process = subprocess.Popen(
            command_list, shell=False, 
            encoding='utf-8',
            bufsize=0,
            stdin=subprocess.DEVNULL,
            universal_newlines=True,
            stdout=subprocess.PIPE, 
            stderr=subprocess.PIPE
            )
        # Poll process for new output until finished
        # Source: https://stackoverflow.com/q/37401654/7769076
        while process.poll() is None:
            nextline = process.stdout.readline()
            sys.stdout.write(nextline)
            sys.stdout.flush()

    except CalledProcessError as err:
        print("CalledProcessError: {0}".format(err))
        sys.exit(1)

    except OSError as err:
        print("OS error: {0}".format(err))
        sys.exit(1)

    except:
        print("Unexpected error:", sys.exc_info()[0])
        raise

    if (process.returncode == 0):
        toc = time.time()
        time1 = str(round(toc - tic))
        return time1
    else:
        return 1

This script call to the above code snipped of train.py does return output but the tqdm output is stopped after 0 seconds and looks like this:

f5b: pbar.set_postfix:   0%|                             | 0/10 [00:00<?, ?it/s]
f5b: pbar.set_postfix:  10%|█▊                | 1/10 [00:00<00:00, 22310.13it/s]

The script call to the original code of train.py returns all output except tqdm output:

Training default configuration
train.py data --use-cuda ...
device: cuda
...

Comments:

  1. shell = False: As python script calls python script. When shell=True, the client script is not called at all
  2. bufsize=0: To prevent buffering
  3. The train.py call is preceded with sys.executable to ensure that the python interpreter of the corresponding conda environment is called when on local machine.

Questions:

  1. Does tqdm.set_postfix prevent passing the progress bar output upstream? I know this happens when tqdm.set_description is invoked, e.g. by:

    pbar.set_description('processed: %d' %(1 + i))

This code contains it:

def train(self, dataloader, max_batches=500, verbose=True, **kwargs):
    with tqdm(total=max_batches, disable=not verbose, **kwargs) as pbar:
        for results in self.train_iter(dataloader, max_batches=max_batches):
            pbar.update(1)
            postfix = {'loss': '{0:.4f}'.format(results['mean_outer_loss'])}

            if 'accuracies_after' in results:
                postfix['accuracy'] = '{0:.4f}'.format(
                    np.mean(results['accuracies_after']))
            pbar.set_postfix(**postfix)
    # for logging
    return results
  1. Is the nested function call the reason why the progress bar is not shown?

The order of calls is experiment.py > train.py > nested.py.

train.py calls the train function in nested.py by:

for epoch in range(args.num_epochs):

results_metatraining = metalearner.train(meta_train_dataloader,
                  max_batches=args.num_batches,
                  verbose=args.verbose,
                  desc='Training',
                  # leave=False
                  leave=True
                  )

Alternatives tried out with no success:

    ### try2
    process = subprocess.Popen(command_list, shell=False, encoding='utf-8',
                               stdin=DEVNULL, stdout=subprocess.PIPE)
    while True:
        output = process.stdout.readline().strip()
        print('output: ' + output)
        if output == '' and process.poll() is not None:  # end of output
            break
        if output: # print output in realtime
            print(output)
    else:
        output = process.communicate()
    process.wait()


    ### try6
    process = subprocess.Popen(command_list, shell=False,
                               stdout=subprocess.PIPE, universal_newlines=True)
    for stdout_line in iter(process.stdout.readline, ""):
        yield stdout_line 
    process.stdout.close()
    return_code = process.wait()
    print('return_code' + str(return_code))
    if return_code:
        raise subprocess.CalledProcessError(return_code, command_list)


    ### try7
    with subprocess.Popen(command_list, stdout=subprocess.PIPE, 
                          bufsize=1, universal_newlines=True) as p:
        while True:
            line = p.stdout.readline()
            if not line:
                break
            print(line)    
        exit_code = p.poll()
Agile Bean
  • 6,437
  • 1
  • 45
  • 53

1 Answers1

0

I think readline is waiting for '\n', and tqdm is not creating new lines, maybe this could help (I did not try):

import io
def execute_experiment(command_list):
    tic = time.time()
    try:
        process = subprocess.Popen(
            command_list, shell=False, 
            encoding='utf-8',
            bufsize=1,
            stdin=subprocess.DEVNULL,
            universal_newlines=True,
            stdout=subprocess.PIPE, 
            stderr=subprocess.STDOUT
            )
        # Poll process for new output until finished
        # Source: https://stackoverflow.com/q/37401654/7769076
        reader = io.TextIOWrapper(process.stdout, encoding='utf8')
        while process.poll() is None:
            char = reader.read(1)
            sys.stdout.write(char)
            sys.stdout.flush()

    except CalledProcessError as err:
        print("CalledProcessError: {0}".format(err))
        sys.exit(1)

    except OSError as err:
        print("OS error: {0}".format(err))
        sys.exit(1)

    except:
        print("Unexpected error:", sys.exc_info()[0])
        raise

    if (process.returncode == 0):
        toc = time.time()
        time1 = str(round(toc - tic))
        return time1
    else:
        return 1
Marcus
  • 275
  • 1
  • 12