[python] os.system output out-of-order using shell pipe

t.py as below:

1
2
3
4
5
import os

print "### before ps"
os.system("ps")
print "### after ps"

logical is quite simple, if we directly run it: python t.py, output as below, nothing special:

1
2
3
4
5
6
7
### before ps
  PID TTY          TIME CMD
 1619 pts/9    00:00:00 python
 1620 pts/9    00:00:00 sh
 1621 pts/9    00:00:00 ps
18701 pts/9    00:00:00 bash
### after ps

However, if we use shell pipe: python t.py | cat, situation is very different:

1
2
3
4
5
6
7
8
  PID TTY          TIME CMD
 1873 pts/9    00:00:00 python
 1874 pts/9    00:00:00 cat
 1875 pts/9    00:00:00 sh
 1876 pts/9    00:00:00 ps
18701 pts/9    00:00:00 bash
### before ps
### after ps

The output of os.system('ps') output first.

Let's have some modify on t.py:

1
2
3
4
5
6
7
8
import os

print "### before ps"
os.system("ps")
print "### after ps"

while True:   # dead loop
    pass

The the output will be like below:

1
2
3
4
5
6
7
/tmp$python t.py | cat
  PID TTY          TIME CMD
 2218 pts/9    00:00:00 python
 2220 pts/9    00:00:00 cat
 2221 pts/9    00:00:00 sh
 2222 pts/9    00:00:00 ps
18701 pts/9    00:00:00 bash

From the log, it becomes more confused, it looks like that script t.py never executes, while later ps do execute. If you just read the log, you will get confused and guess it should never happens. You would never think it was stuck in while loop.

It's not limited to Python

Actually, it's not limit to Python, os.system() call is a simple implement from system() call in C.

1
2
3
4
5
6
7
8
9
#include <stdlib.h>
#include <stdio.h>

int main() {
    printf("### before ps\n");
    system("ps");
    printf("### after ps\n");
    return 0;
}

output is the same after pipe:

1
2
3
4
5
6
7
8
9
/tmp$./a.out | cat
  PID TTY          TIME CMD
 5909 pts/21   00:00:00 bash
 6707 pts/21   00:00:00 a.out
 6708 pts/21   00:00:00 cat
 6709 pts/21   00:00:00 sh
 6710 pts/21   00:00:00 ps
### before ps
### after ps

Root Cause

In fact, it's like a currency issue when multiple process write to the same stdout.

The calling of system() will create another process, while a.out is trying write to the same stdout, too.

system() executes a command specified in command by calling /bin/sh -c command, and returns after the command has been completed.

The output of a.out might not have been flush before ps exit, so output of ps show first in pipe. What if a.out print a lot of message, so that buffer can be flush into stdout in time:

1
2
3
4
5
6
7
8
9
10
11
#include <stdlib.h>
#include <stdio.h>

int main() {
        int i;
        for (i = 0; i < 1000; i++)  // print mass log
            printf("### before ps\n");
        system("ps");
        printf("### after ps\n");
        return 0;
}

Here we can see clearly log conflict from output.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
....
### before ps
### before ps
### before ps
### before  PID TTY          TIME CMD
 5909 pts/21   00:00:00 bash
12581 pts/21   00:00:00 a.out
12582 pts/21   00:00:00 cat
12583 pts/21   00:00:00 sh
12584 pts/21   00:00:00 ps
 ps
### before ps
### before ps
### before ps
### before ps
...

Solution

If we fflush(stdout) before calling system(), this problem will go away.

1
2
3
4
5
6
7
8
9
10
#include <stdlib.h>
#include <stdio.h>

int main() {
        printf("### before ps\n");
        fflush(stdout);  // flush stdout before running 'ps'
        system("ps");
        printf("### after ps\n");
        return 0;
}

output:

1
2
3
4
5
6
7
8
9
oneyoung:/tmp$./a.out | cat
### before ps
  PID TTY          TIME CMD
 5909 pts/21   00:00:00 bash
10667 pts/21   00:00:00 a.out
10668 pts/21   00:00:00 cat
10669 pts/21   00:00:00 sh
10670 pts/21   00:00:00 ps
### after ps

留言