Subprocess output takes far too long to return - 11.5 sec

I have a project in which I am using subprocess to call a C program and read an output. It takes 11.5 sec to return from the output request. The time is very consistent regardless of the size of the output or the complexity of parameters passed to the actual subprocess being used. Where is this HUGE delay coming from?

The following code is a test of this problem. You can see the times involved in the output printout.

The following is the C program - test.c.

#include <stdlib.h>
#include <string.h>
#include <stdio.h>
#include <math.h>
#include <stdbool.h>
#include <time.h>

int main()
{
    printf("Hello \n");
    return 0;
}

The following is the Python program - test.py:

#!/usr/bin/env python3
# -*- coding: utf-8 -*-
#
# Copyright 2023 gr-FT8_RXTX author.
#
# SPDX-License-Identifier: GPL-3.0-or-later
#




import time
import subprocess
from datetime import datetime

cmd_args = ['/home/wa4ywm/gr-ft8_rxtx/Test/test']

now = float(datetime.now().strftime('%S.%f'))
print ("Before ft8_decode = ", now)

ft8_decode = subprocess.Popen(cmd_args, stdout=subprocess.PIPE)

now = float(datetime.now().strftime('%S.%f'))
print ("After ft8_decode = ", now)

output = ft8_decode.stdout.read()

now = float(datetime.now().strftime('%S.%f'))
print ("After output = ", now)

print(output.decode())

The following is the output:

wa4ywm@raspberrypi:~/gr-ft8_rxtx/Test $ python3 test.py
Before ft8_decode =  8.022773
After ft8_decode =  8.025588
After output =  19.528749
Hello

I am running on RPi with the bookworm OS with Python 3.11.

I have spent many hours reading about subprocess, scouring forums and posting on Stackoverflow with no results.

Please help.

Popen starts the subprocess and then returns immediately.

Try waiting for it to finish with ft8_decode.wait().

Does that make a difference?

Hello,

to measure the time delay, you can use this:

import time, sys
timer = time.perf_counter if sys.platform[:3] == 'win' else time.time

start = timer()             # Start timer reference here

# *** part of script that you would like to measure latency ****

elapsed = timer() - start   # Measure elapsed time here

print('Elapsed time is: ', elapsed)

Try using the higher level API subprocess.run() withs its capture output option. Popen take some care to use well.

Why is this different from what I am already doing to measure the delay?

I placed the ft8_decode.wait after the subprocess call and the code waited 11.5 sec before moving on to print the “After ft8_decode” time.

There is no need for either the str or float conversion. It provides the net elapsed time.

From your test results, it appears that the ft8_decode.stdout.read() is the line that is causing the issue. Can you test it with this code as a double verification?

start = timer()             # Start timer reference here

output = ft8_decode.stdout.read()

elapsed = timer() - start   # Measure elapsed time here

I used run() initially – same result. I tried using Popen hoping for a solution.

How long does the command you are running take in a terminal?
On my RPi I ran this test (my RPi is running Fedora not Raspbian):

$ time python -c "from subprocess import run;run('/bin/true')"

real	0m0.244s
user	0m0.199s
sys	0m0.037s

The elapsed time is 11.47 sec.

Your C code is so simple. Is there a special reason why you are including all of these libraries? For testing purposes, can you comment them out (maybe except for stdio).

Also, for this test, don’t use (comment out) your now / print pairs.

The extra includes were left over from my original file before I cut everything down to a test file. I commented out all except stdio. Also commented out the now/print pairs in test.py. The elapsed time is 11.50.

I am running in a terminal

Here is something extra that might help. I am using the Geany IDE. There are 2 executable processes to use - Build and Make. When I do a Build, the code runs properly - no delay. When I run Make, the delay is present.

The Build line is:
gcc -Wall -o “test” “test.c”

The Make process is:
cc -03 -ggdb3 -fsanitize=address -std=c11 -I. -c -o test.o test.c
cc -lm -fsanitize=address -Wall -o test test.o

The Makefile I am using is a distillation of a Makefile used for the original project. Could this Make be the issue?

Can you create a new project such that there are no dependencies to the original project?
Then re-try.

By the way, since it is only one small script, is there really a need to create a “project”? Try running it as a standalone module (file).

Isn’t that what I am doing when I just do Build?

I of course can’t do that for the larger project which has many dependencies - and the same problem.

Your script is very small … just a handful of lines. Can you try running it from IDLE? Is the delay being generated by the Geany IDE?

@barry-scott showed that he does not get the delay that you are experiencing when he performs the test. Can you replicate his environment / test set-up?

Yes, this is correct. But what we are attempting to do here is to isolate / locate the source of the delay. Is it an IDE issue, maybe v3.11 issue, we don’t yet know.

As from your own tests:

output = ft8_decode.stdout.read()

Is the source of your delay. But why?

I executed Barry’s test with the following result:

real 0.282s
user 0/232s
sys 0.04s

Not sure where the disconnect is coming from.

As you have tested at your end, your latency is nowhere near the 11.5 s you got as per your original post.

I went ahead and performed the test myself:

import subprocess
import time, sys
timer = time.perf_counter if sys.platform[:3] == 'win' else time.time

start = timer()

cmd_args = ['./test']
ft8_decode = subprocess.Popen(cmd_args, stdout=subprocess.PIPE)
output = ft8_decode.stdout.read()

elapsed = timer() - start

print(output.decode())
print(f'Time elapsed: {elapsed} s')

This is what I got using IDLE v3.13:

I ran your code and I still get the delay. So I generated the executable on the command line - it works. This would seem to point to some bizarre issue with Geany. Or a linker issue. Maybe it is an issue with bookworm,