Multiprocessing: Will the OS let a sleeping process sleep longer, simply because it is sleeping?

Python Help
1

I’m parsing CSV files and writing them to HDF5 using multiple processors and have observed a curious behaviour. The OS seems to let sleeping processes sleep longer.

All writes to HDF5 are concurrent thanks to mplite, such as this:

    @timeout
    def mp_write_column(self, values, column_key=None):  # column task.
        """
        multi processing helper for writing column data.
        """
        with h5py.File(self.path, READWRITE) as h5:
            new_page = Page(values)
            if not column_key:
                column_key = self.new_id('/column')
            dset = h5.create_dataset(name=f'/column/{column_key}', dtype=h5py.Empty('f'))
            dset.attrs['pages'] = json.dumps([new_page.group])
            dset.attrs['length'] = len(new_page)
            return column_key

… are wrapped with this friendly decorator:

TIMEOUT = 10000  # maximum seconds tolerance waiting for OS to release hdf5 write lock

def timeout(func):
    @functools.wraps(func)
    def wrapper(*args,**kwargs):
        t = 0
        start = time.time()
        while time.time() - start < TIMEOUT:
            try:
                begin = time.process_time()
                result = func(*args,**kwargs)
                end = time.process_time()
                print(f"waited {t} msec to exec. {func.__name__} in {round(1000*(end-begin))} msec")
                return result
            except OSError:
                dt = random.randint(0,500)
                t+=dt
                time.sleep(dt/1000)  # <--- emphasis here!
            
        raise OSError(f"couldn't write to disk (slept {t} msec")
    return wrapper

When I process 7.2Gb csv test file I see this log output from the decorator:
(notice how there is always some process that is waiting far longer than others).

waited 0 msec to exec. mp_write_column in 1109 msec
waited 0 msec to exec. mp_write_column in 891 msec
waited 0 msec to exec. mp_write_column in 750 msec
waited 0 msec to exec. mp_write_column in 750 msec
waited 0 msec to exec. mp_write_column in 812 msec
waited 0 msec to exec. mp_write_table in 16 msec
waited 4232 msec to exec. mp_write_column in 797 msec   # <---- emphasis!
waited 0 msec to exec. mp_write_column in 984 msec
waited 5076 msec to exec. mp_write_column in 859 msec   # <---- emphasis!
waited 0 msec to exec. mp_write_column in 953 msec
waited 0 msec to exec. mp_write_column in 844 msec
waited 0 msec to exec. mp_write_column in 828 msec
waited 0 msec to exec. mp_write_column in 953 msec
waited 10122 msec to exec. mp_write_column in 781 msec   # <---- emphasis!
waited 0 msec to exec. mp_write_column in 875 msec
waited 0 msec to exec. mp_write_column in 766 msec
waited 0 msec to exec. mp_write_column in 750 msec
waited 0 msec to exec. mp_write_column in 828 msec
waited 0 msec to exec. mp_write_table in 0 msec
waited 13716 msec to exec. mp_write_column in 844 msec   # <---- emphasis!
waited 0 msec to exec. mp_write_column in 1188 msec
waited 0 msec to exec. mp_write_column in 891 msec
waited 0 msec to exec. mp_write_column in 859 msec
waited 0 msec to exec. mp_write_column in 922 msec
waited 0 msec to exec. mp_write_table in 0 msec

What is going on?

I am guessing that the OS looks at a process that’s sleeping and decides: “Oh - you’re a sleeping proc, you can’t be important. I’ll look at you, once all others have been dealt with.”

With this assumption I deduce the this causes the OS not to touch the sleeping process until IO is busy, whereby the proc will get OSError can't obtain filesystem lock and it will enter sleep mode again.

Hence I am guessing the “complex” dynamics of a sleeping process is that it will sleep even longer.

Right? / Wrong? And can/should I do something about it?

Here is the whole log with os.getpid:


15824 waited 0 msec to exec. mp_write_column in 1031 msec
15824 waited 0 msec to exec. mp_write_column in 719 msec
15824 waited 0 msec to exec. mp_write_column in 609 msec
15824 waited 0 msec to exec. mp_write_column in 609 msec
15824 waited 0 msec to exec. mp_write_column in 688 msec
15824 waited 0 msec to exec. mp_write_table in 0 msec

14940 waited 3190 msec to exec. mp_write_column in 781 msec
14940 waited 0 msec to exec. mp_write_column in 969 msec
14940 waited 0 msec to exec. mp_write_column in 1016 msec
14940 waited 0 msec to exec. mp_write_column in 828 msec
14940 waited 0 msec to exec. mp_write_column in 953 msec
14940 waited 0 msec to exec. mp_write_table in 0 msec

17172 waited 8452 msec to exec. mp_write_column in 906 msec
17172 waited 0 msec to exec. mp_write_column in 1156 msec
17172 waited 0 msec to exec. mp_write_column in 1000 msec
17172 waited 0 msec to exec. mp_write_column in 1062 msec
17172 waited 0 msec to exec. mp_write_column in 922 msec
17172 waited 0 msec to exec. mp_write_table in 0 msec

15824 waited 2332 msec to exec. mp_write_column in 891 msec
15824 waited 0 msec to exec. mp_write_column in 1094 msec
15824 waited 0 msec to exec. mp_write_column in 953 msec
15824 waited 0 msec to exec. mp_write_column in 875 msec
15824 waited 0 msec to exec. mp_write_column in 1125 msec
15824 waited 0 msec to exec. mp_write_table in 0 msec

13196 waited 18320 msec to exec. mp_write_column in 922 msec
13196 waited 0 msec to exec. mp_write_column in 1141 msec
13196 waited 0 msec to exec. mp_write_column in 984 msec
13196 waited 0 msec to exec. mp_write_column in 828 msec
13196 waited 0 msec to exec. mp_write_column in 812 msec
13196 waited 0 msec to exec. mp_write_table in 0 msec

17456 waited 22267 msec to exec. mp_write_column in 1297 msec
17456 waited 0 msec to exec. mp_write_column in 1141 msec
17456 waited 0 msec to exec. mp_write_column in 938 msec
17456 waited 0 msec to exec. mp_write_column in 797 msec
17456 waited 0 msec to exec. mp_write_column in 859 msec
17456 waited 0 msec to exec. mp_write_table in 0 msec

18244 waited 27256 msec to exec. mp_write_column in 906 msec
18244 waited 0 msec to exec. mp_write_column in 1578 msec
18244 waited 0 msec to exec. mp_write_column in 906 msec
18244 waited 0 msec to exec. mp_write_column in 781 msec
18244 waited 0 msec to exec. mp_write_column in 906 msec
18244 waited 0 msec to exec. mp_write_table in 0 msec

17172 waited 11936 msec to exec. mp_write_column in 906 msec
17172 waited 0 msec to exec. mp_write_column in 1219 msec
17172 waited 0 msec to exec. mp_write_column in 1047 msec
17172 waited 0 msec to exec. mp_write_column in 797 msec
17172 waited 0 msec to exec. mp_write_column in 812 msec
17172 waited 0 msec to exec. mp_write_table in 0 msec

14940 waited 22050 msec to exec. mp_write_column in 875 msec
14940 waited 0 msec to exec. mp_write_column in 1141 msec
14940 waited 0 msec to exec. mp_write_column in 984 msec
14940 waited 0 msec to exec. mp_write_column in 906 msec
14940 waited 0 msec to exec. mp_write_column in 875 msec
14940 waited 0 msec to exec. mp_write_table in 0 msec

18244 waited 2616 msec to exec. mp_write_column in 906 msec
18244 waited 0 msec to exec. mp_write_column in 1062 msec
18244 waited 0 msec to exec. mp_write_column in 906 msec
18244 waited 0 msec to exec. mp_write_column in 891 msec
18244 waited 0 msec to exec. mp_write_column in 1109 msec
18244 waited 0 msec to exec. mp_write_table in 0 msec

15824 waited 21785 msec to exec. mp_write_column in 969 msec
15824 waited 0 msec to exec. mp_write_column in 1109 msec
15824 waited 0 msec to exec. mp_write_column in 969 msec
15824 waited 0 msec to exec. mp_write_column in 750 msec
15824 waited 0 msec to exec. mp_write_column in 1016 msec
15824 waited 0 msec to exec. mp_write_table in 0 msec

17456 waited 16903 msec to exec. mp_write_column in 1047 msec
17456 waited 0 msec to exec. mp_write_column in 1094 msec
17456 waited 0 msec to exec. mp_write_column in 1172 msec
17456 waited 0 msec to exec. mp_write_column in 812 msec
17456 waited 0 msec to exec. mp_write_column in 859 msec
17456 waited 0 msec to exec. mp_write_table in 0 msec

13696 waited 57751 msec to exec. mp_write_column in 1078 msec
13696 waited 0 msec to exec. mp_write_column in 1312 msec
13696 waited 0 msec to exec. mp_write_column in 906 msec
13696 waited 0 msec to exec. mp_write_column in 766 msec
13696 waited 0 msec to exec. mp_write_column in 859 msec
13696 waited 0 msec to exec. mp_write_table in 0 msec

17172 waited 16995 msec to exec. mp_write_column in 906 msec
17172 waited 0 msec to exec. mp_write_column in 1203 msec
17172 waited 0 msec to exec. mp_write_column in 1094 msec
17172 waited 0 msec to exec. mp_write_column in 828 msec
17172 waited 0 msec to exec. mp_write_column in 875 msec
17172 waited 0 msec to exec. mp_write_table in 16 msec

14940 waited 16833 msec to exec. mp_write_column in 891 msec
14940 waited 0 msec to exec. mp_write_column in 1109 msec
14940 waited 0 msec to exec. mp_write_column in 1094 msec
14940 waited 0 msec to exec. mp_write_column in 812 msec
14940 waited 0 msec to exec. mp_write_column in 812 msec
14940 waited 0 msec to exec. mp_write_table in 0 msec

13196 waited 41483 msec to exec. mp_write_column in 984 msec
13196 waited 0 msec to exec. mp_write_column in 1203 msec
13196 waited 0 msec to exec. mp_write_column in 984 msec
13196 waited 0 msec to exec. mp_write_column in 1062 msec
13196 waited 0 msec to exec. mp_write_column in 906 msec
13196 waited 0 msec to exec. mp_write_table in 16 msec

15824 waited 16946 msec to exec. mp_write_column in 1031 msec
15824 waited 0 msec to exec. mp_write_column in 1141 msec
15824 waited 0 msec to exec. mp_write_column in 906 msec
15824 waited 0 msec to exec. mp_write_column in 828 msec
15824 waited 0 msec to exec. mp_write_column in 1172 msec
15824 waited 0 msec to exec. mp_write_table in 16 msec

18244 waited 26612 msec to exec. mp_write_column in 1031 msec
18244 waited 0 msec to exec. mp_write_column in 1219 msec
18244 waited 0 msec to exec. mp_write_column in 938 msec
18244 waited 0 msec to exec. mp_write_column in 844 msec
18244 waited 0 msec to exec. mp_write_column in 1094 msec
18244 waited 0 msec to exec. mp_write_table in 16 msec

17456 waited 22633 msec to exec. mp_write_column in 1016 msec
17456 waited 0 msec to exec. mp_write_column in 1031 msec
17456 waited 0 msec to exec. mp_write_column in 875 msec
17456 waited 0 msec to exec. mp_write_column in 781 msec
17456 waited 0 msec to exec. mp_write_column in 844 msec
17456 waited 0 msec to exec. mp_write_table in 0 msec

13196 waited 7084 msec to exec. mp_write_column in 1234 msec
13196 waited 0 msec to exec. mp_write_column in 1172 msec
13196 waited 0 msec to exec. mp_write_column in 906 msec
13196 waited 0 msec to exec. mp_write_column in 859 msec
13196 waited 0 msec to exec. mp_write_column in 906 msec
13196 waited 0 msec to exec. mp_write_table in 0 msec

15824 waited 7851 msec to exec. mp_write_column in 1047 msec
15824 waited 0 msec to exec. mp_write_column in 1359 msec
15824 waited 0 msec to exec. mp_write_column in 953 msec
15824 waited 0 msec to exec. mp_write_column in 797 msec
15824 waited 0 msec to exec. mp_write_column in 938 msec
15824 waited 0 msec to exec. mp_write_table in 0 msec

14940 waited 21827 msec to exec. mp_write_column in 953 msec
14940 waited 0 msec to exec. mp_write_column in 1250 msec
14940 waited 0 msec to exec. mp_write_column in 1125 msec
14940 waited 0 msec to exec. mp_write_column in 812 msec
14940 waited 0 msec to exec. mp_write_column in 812 msec
14940 waited 0 msec to exec. mp_write_table in 16 msec

13196 waited 1602 msec to exec. mp_write_column in 906 msec
13196 waited 0 msec to exec. mp_write_column in 1109 msec
13196 waited 0 msec to exec. mp_write_column in 1047 msec
13196 waited 0 msec to exec. mp_write_column in 969 msec
13196 waited 0 msec to exec. mp_write_column in 922 msec
13196 waited 0 msec to exec. mp_write_table in 0 msec

15824 waited 2030 msec to exec. mp_write_column in 1359 msec
15824 waited 0 msec to exec. mp_write_column in 1250 msec
15824 waited 0 msec to exec. mp_write_column in 1109 msec
15824 waited 0 msec to exec. mp_write_column in 1109 msec
15824 waited 0 msec to exec. mp_write_column in 938 msec
15824 waited 0 msec to exec. mp_write_table in 16 msec

18244 waited 23014 msec to exec. mp_write_column in 1062 msec
18244 waited 0 msec to exec. mp_write_column in 1219 msec
18244 waited 0 msec to exec. mp_write_column in 984 msec
18244 waited 0 msec to exec. mp_write_column in 1266 msec
18244 waited 0 msec to exec. mp_write_column in 1109 msec
18244 waited 0 msec to exec. mp_write_table in 0 msec

13196 waited 2857 msec to exec. mp_write_column in 1125 msec
13196 waited 0 msec to exec. mp_write_column in 1297 msec
13196 waited 0 msec to exec. mp_write_column in 1047 msec
13196 waited 0 msec to exec. mp_write_column in 1125 msec
13196 waited 0 msec to exec. mp_write_column in 938 msec
13196 waited 0 msec to exec. mp_write_table in 0 msec

15824 waited 2483 msec to exec. mp_write_column in 938 msec
15824 waited 0 msec to exec. mp_write_column in 1203 msec
15824 waited 0 msec to exec. mp_write_column in 906 msec
15824 waited 0 msec to exec. mp_write_column in 891 msec
15824 waited 0 msec to exec. mp_write_column in 1172 msec
15824 waited 0 msec to exec. mp_write_table in 16 msec

13696 waited 64654 msec to exec. mp_write_column in 969 msec
13696 waited 0 msec to exec. mp_write_column in 1219 msec
13696 waited 0 msec to exec. mp_write_column in 1000 msec
13696 waited 0 msec to exec. mp_write_column in 812 msec
13696 waited 0 msec to exec. mp_write_column in 1062 msec
13696 waited 0 msec to exec. mp_write_table in 0 msec

17456 waited 39378 msec to exec. mp_write_column in 1109 msec
17456 waited 0 msec to exec. mp_write_column in 1203 msec
17456 waited 0 msec to exec. mp_write_column in 1047 msec
17456 waited 0 msec to exec. mp_write_column in 859 msec
17456 waited 0 msec to exec. mp_write_column in 875 msec
17456 waited 0 msec to exec. mp_write_table in 0 msec

18244 waited 12399 msec to exec. mp_write_column in 1328 msec
18244 waited 0 msec to exec. mp_write_column in 1188 msec
18244 waited 0 msec to exec. mp_write_column in 1000 msec
18244 waited 0 msec to exec. mp_write_column in 875 msec
18244 waited 0 msec to exec. mp_write_column in 891 msec
18244 waited 0 msec to exec. mp_write_table in 0 msec

14940 waited 33549 msec to exec. mp_write_column in 969 msec
14940 waited 0 msec to exec. mp_write_column in 1328 msec
14940 waited 0 msec to exec. mp_write_column in 891 msec
14940 waited 0 msec to exec. mp_write_column in 828 msec
14940 waited 0 msec to exec. mp_write_column in 922 msec
14940 waited 0 msec to exec. mp_write_table in 16 msec

13696 waited 7038 msec to exec. mp_write_column in 953 msec
13696 waited 0 msec to exec. mp_write_column in 1234 msec
17456 waited 4320 msec to exec. mp_write_column in 1156 msec
17456 waited 0 msec to exec. mp_write_column in 922 msec
17456 waited 0 msec to exec. mp_write_column in 797 msec
13696 waited 2805 msec to exec. mp_write_column in 750 msec
13696 waited 0 msec to exec. mp_write_column in 812 msec
13696 waited 0 msec to exec. mp_write_column in 844 msec
13696 waited 0 msec to exec. mp_write_table in 0 msec

17456 waited 2365 msec to exec. mp_write_column in 1109 msec
17456 waited 0 msec to exec. mp_write_column in 969 msec
17456 waited 0 msec to exec. mp_write_table in 16 msec

14940 waited 2435 msec to exec. mp_write_column in 922 msec
14940 waited 0 msec to exec. mp_write_column in 1094 msec
14940 waited 0 msec to exec. mp_write_column in 969 msec
14940 waited 0 msec to exec. mp_write_column in 1062 msec
14940 waited 0 msec to exec. mp_write_column in 1250 msec
14940 waited 0 msec to exec. mp_write_table in 0 msec

17172 waited 95376 msec to exec. mp_write_column in 1156 msec
17172 waited 0 msec to exec. mp_write_column in 1266 msec
17172 waited 0 msec to exec. mp_write_column in 953 msec
17172 waited 0 msec to exec. mp_write_column in 875 msec
17172 waited 0 msec to exec. mp_write_column in 1031 msec
17172 waited 0 msec to exec. mp_write_table in 0 msec

18244 waited 17090 msec to exec. mp_write_column in 734 msec
18244 waited 0 msec to exec. mp_write_column in 734 msec
18244 waited 0 msec to exec. mp_write_column in 609 msec
18244 waited 0 msec to exec. mp_write_column in 609 msec
18244 waited 0 msec to exec. mp_write_column in 672 msec
18244 waited 0 msec to exec. mp_write_table in 0 msec

17456 waited 5570 msec to exec. mp_write_column in 656 msec
17456 waited 0 msec to exec. mp_write_column in 906 msec
17456 waited 0 msec to exec. mp_write_column in 719 msec
17456 waited 0 msec to exec. mp_write_column in 594 msec
17456 waited 0 msec to exec. mp_write_column in 672 msec
17456 waited 0 msec to exec. mp_write_table in 0 msec

13196 waited 44126 msec to exec. mp_write_column in 672 msec
13196 waited 0 msec to exec. mp_write_column in 750 msec
13196 waited 0 msec to exec. mp_write_column in 625 msec
13196 waited 0 msec to exec. mp_write_column in 625 msec
13196 waited 0 msec to exec. mp_write_column in 797 msec
13196 waited 0 msec to exec. mp_write_table in 0 msec

15824 waited 42932 msec to exec. mp_write_column in 812 msec
15824 waited 0 msec to exec. mp_write_column in 797 msec
15824 waited 0 msec to exec. mp_write_column in 609 msec
15824 waited 0 msec to exec. mp_write_column in 625 msec
15824 waited 0 msec to exec. mp_write_column in 719 msec
15824 waited 0 msec to exec. mp_write_table in 0 msec

14940 waited 13789 msec to exec. mp_write_column in 422 msec
14940 waited 0 msec to exec. mp_write_column in 484 msec
14940 waited 0 msec to exec. mp_write_column in 422 msec
14940 waited 0 msec to exec. mp_write_column in 438 msec
14940 waited 0 msec to exec. mp_write_column in 656 msec
14940 waited 0 msec to exec. mp_write_table in 0 msec

13696 waited 21334 msec to exec. mp_write_column in 656 msec
13696 waited 0 msec to exec. mp_write_column in 750 msec
13696 waited 0 msec to exec. mp_write_column in 688 msec
13696 waited 0 msec to exec. mp_write_column in 625 msec
13696 waited 0 msec to exec. mp_write_column in 656 msec
13696 waited 0 msec to exec. mp_write_table in 0 msec

import took 365.2052 secs.
2

I am familiar neither with HDF5 nor with mplite. Maybe I can help with some generic information.

Process scheduling depends on the operating system (here I guess Linux?) and the scheduling strategy / class / policy or how it is called in the OS.

Information about process scheduling on Linux can be found here: Fixing SCHED_IDLE [LWN.net] , sched(7) - Linux manual page

Linux uses the nanosleep() system call to implement sleep. In the notes we can see that the sleeping time can be longer because of:

  1. rounding up according to USER_HZ, I think it is normally 100 Hz i.e. rounding to 10 ms
  2. simply because there is no available CPU to process the threat/process
  3. drift because of sleep restarts (when the process is interrupted during sleep)

If the interval specified in req is not an exact multiple of the
granularity underlying clock (see time(7)), then the interval
will be rounded up to the next multiple. Furthermore, after the
sleep completes, there may still be a delay before the CPU
becomes free to once again execute the calling thread.

The fact that nanosleep() sleeps for a relative interval can be
problematic if the call is repeatedly restarted after being
interrupted by signals, since the time between the interruptions
and restarts of the call will lead to drift in the time when the
sleep finally completes.

I think in your case it can be the point 2. How many processes do you run in parallel and how many CPUs do you have available? Are there other processes active on the system when you run the task? Do not they have higher priorities?

To get better insight into the sleep calls I would print the arguments and time passed in the individual calls (not just the sum). Something like:

time_before_sleep = time.perf_counter()
time.sleep(dt/1000)  # <--- emphasis here!
time_after_sleep = time.perf_counter()
print(f"sleep({dt/1000}), elapsed: {time_after_sleep - time_before_sleep}")

Some suggestions for your code:

Inside the while loop try should be just around the func() call:

            begin = time.process_time()
            try:
                result = func(*args,**kwargs)
            except OSError:
                dt = random.randint(0,500)
                t+=dt
                time.sleep(dt/1000)  # <--- emphasis here!
            else:
                end = time.process_time()
                print(f"waited {t} msec to exec. {func.__name__} in {round(1000*(end-begin))} msec")
                return result

To measure the time elapsed you should not use time.time(). It is not monotonic. Use time.perf_counter() or the _ns variant of it returning integer.

1 Like
3

I have as many processes as CPUs minus 1. The priorities are OS only + python.

Good hint. Thank you. Following your recommendation I’ve updated the decorator so that planned vs. actual time is recorded:


def timeout(func):
    @functools.wraps(func)
    def wrapper(*args,**kwargs):
        waited = 0.0
        planned= 0.0
        while waited < TIMEOUT:
            try:
                begin = time.perf_counter()
                result = func(*args,**kwargs)
                end = time.perf_counter()
                print(f"{getpid()} waited {int(waited)} msec (planned {planned}) to exec. {func.__name__} for {round(1000*(end-begin))} msec")
                return result
            except OSError:
                wait = random.randint(25, 500)
                planned += wait
                t1 = time.perf_counter()
                time.sleep(wait/1000)
                t2 = time.perf_counter()
                waited += (t2-t1)*1000

        raise OSError(f"couldn't write to disk (slept {waited} msec")
    return wrapper

The new log looks like this (below) and the interrupt lag is definitely visible (logs follow below) as:

18300 waited 3243 msec (planned 3173.0) to exec. mp_write_column for 807 msec

So around ~ 2.6% drift.

New logs:

6180 waited 0 msec (planned 0.0) to exec. mp_write_column for 1169 msec
6180 waited 0 msec (planned 0.0) to exec. mp_write_column for 753 msec
6180 waited 0 msec (planned 0.0) to exec. mp_write_column for 614 msec
6180 waited 0 msec (planned 0.0) to exec. mp_write_column for 596 msec
6180 waited 0 msec (planned 0.0) to exec. mp_write_column for 667 msec
6180 waited 0 msec (planned 0.0) to exec. mp_write_table for 9 msec

18300 waited 3243 msec (planned 3173.0) to exec. mp_write_column for 807 msec
18300 waited 0 msec (planned 0.0) to exec. mp_write_column for 920 msec
18300 waited 0 msec (planned 0.0) to exec. mp_write_column for 855 msec
18300 waited 0 msec (planned 0.0) to exec. mp_write_column for 1006 msec
18300 waited 0 msec (planned 0.0) to exec. mp_write_column for 806 msec
18300 waited 0 msec (planned 0.0) to exec. mp_write_table for 5 msec

13532 waited 8084 msec (planned 7869.0) to exec. mp_write_column for 909 msec
13532 waited 0 msec (planned 0.0) to exec. mp_write_column for 1091 msec
13532 waited 0 msec (planned 0.0) to exec. mp_write_column for 930 msec
13532 waited 0 msec (planned 0.0) to exec. mp_write_column for 807 msec
13532 waited 0 msec (planned 0.0) to exec. mp_write_column for 972 msec
13532 waited 0 msec (planned 0.0) to exec. mp_write_table for 3 msec

2304 waited 11950 msec (planned 11650.0) to exec. mp_write_column for 921 msec
2304 waited 0 msec (planned 0.0) to exec. mp_write_column for 1188 msec
17632 waited 13965 msec (planned 13485.0) to exec. mp_write_column for 1217 msec
17632 waited 0 msec (planned 0.0) to exec. mp_write_column for 963 msec
17632 waited 0 msec (planned 0.0) to exec. mp_write_column for 788 msec
17632 waited 0 msec (planned 0.0) to exec. mp_write_column for 1043 msec
17632 waited 0 msec (planned 0.0) to exec. mp_write_column for 870 msec
17632 waited 0 msec (planned 0.0) to exec. mp_write_table for 3 msec

6180 waited 8629 msec (planned 8327.0) to exec. mp_write_column for 796 msec
6180 waited 0 msec (planned 0.0) to exec. mp_write_column for 1235 msec
6180 waited 0 msec (planned 0.0) to exec. mp_write_column for 853 msec

15068 waited 22314 msec (planned 21569.0) to exec. mp_write_column for 770 msec
15068 waited 0 msec (planned 0.0) to exec. mp_write_column for 942 msec
15068 waited 0 msec (planned 0.0) to exec. mp_write_column for 781 msec
15068 waited 0 msec (planned 0.0) to exec. mp_write_column for 779 msec
15068 waited 0 msec (planned 0.0) to exec. mp_write_column for 870 msec
15068 waited 0 msec (planned 0.0) to exec. mp_write_table for 4 msec

13664 waited 25846 msec (planned 24922.0) to exec. mp_write_column for 1092 msec
13664 waited 0 msec (planned 0.0) to exec. mp_write_column for 1069 msec
13664 waited 0 msec (planned 0.0) to exec. mp_write_column for 738 msec
13664 waited 0 msec (planned 0.0) to exec. mp_write_column for 819 msec
13664 waited 0 msec (planned 0.0) to exec. mp_write_column for 839 msec
13664 waited 0 msec (planned 0.0) to exec. mp_write_table for 3 msec

Also good to point out that the effective minimal sleep is 10ms. Thank you !