weird clocking in python datetime.now()

TestProcessPool.py

from concurrent.futures import ProcessPoolExecutor
import random,os
from datetime import datetime
import multiprocessing
from multiprocessing import Process, Queue, Manager
from multiprocessing.sharedctypes import Value, Array
import time, random
import threading


m = multiprocessing.Manager()
queue = m.Queue()

def worker(queue, index, logfile):
    starttime = datetime.now()
    print('%s: %s/%s:start worker: index=%s' % (str(starttime),os.getpid(),  threading.currentThread().getName(), index))
    line = 'radfjljfads fljk asdjfajskdfjklas dflkasdjflkjvlckxzjlkjasdflkjasdlkfasdf'
    lines = [line for i in xrange(5000000)]
    convertline = '\n'.join(lines)
    filename = '/tmp/aaa%s.%s' % (int(time.time()*1000), random.randint(10000, 99999))

    with open(filename, 'w+') as f:
        f.write(convertline)

    print('%s/%s: %s----%s' % (os.getpid(),  threading.currentThread().getName(), filename, len(convertline)))
    returntime = datetime.now()
    queue.put((index, starttime, returntime, logfile, filename))
    # return (index, starttime, returntime, logfile, filename)

def done_callback():
    done_callback_starttime = datetime.now()

    try:
        print('done_callback')
        (index, starttime, returntime, logfile, filename) = queue.get(block=True)

        with open(filename, 'r') as f: 
            convertline = f.read()
            print('%s++++++%s' % (filename, len(convertline)))
        os.remove(filename)
        
        print('done: %s' % len(convertline))

        endtime = datetime.now()
        diff = endtime-starttime # total time
        diff2 = returntime - 
        
        
        
        
         # worker time
        diff3 = done_callback_starttime - returntime # queue time
        diff4 = endtime - done_callback_starttime # done time

        print('%s - %s: pid(%s/%s):done_callback: index=%s, takes(%s, %s, %s, %s)' % (str(endtime), str(starttime), os.getpid(),  threading.currentThread().getName(), index, diff, diff2, diff3, diff4))
    except Exception as e:
        print(e)

def done_worker():
    while True:
        # print('quesize = %s' % len(queue))
        done_callback()



def que():
    qmax = 1000

    t = threading.Thread(target=done_worker)
    t.name='done_worker'
    t.start()
    with ProcessPoolExecutor() as executor:
        for index in xrange(10000):
            # print('%s: pid(%s):submit: index=%s' % (str(datetime.now()), os.getpid(), index))
            while len(executor._pending_work_items) > qmax:
                time.sleep(3)
            future = executor.submit(worker, queue, index, 'filename_'+str(index))

            # future.add_done_callback(done_callback)



def main():
    que()
    time.sleep(100)

if __name__ == '__main__':
    main()

/tmp/aaa1516530859892.66584++++++369999999
done: 369999999
2018-01-21 18:34:30.544923 - 2018-01-21 18:34:19.233702: pid(4671/done_worker):done_callback: index=115, takes(0:00:11.311221, 0:00:10.764203, 0:00:00.145077, 0:00:00.401941)
done_callback
4678/MainThread: /tmp/aaa1516530861245.30010----369999999
2018-01-21 18:34:31.351347: 4678/MainThread:start worker: index=124
/tmp/aaa1516530861245.30010++++++369999999
done: 369999999
2018-01-21 18:34:32.714023 - 2018-01-21 18:34:20.719578: pid(4671/done_worker):done_callback: index=116, takes(0:00:11.994445, 0:00:10.586876, -1 day, 23:59:59.261755, 0:00:02.145814)
done_callback
4677/MainThread: /tmp/aaa1516530862405.85983----369999999
2018-01-21 18:34:34.064962: 4677/MainThread:start worker: index=125
/tmp/aaa1516530862405.85983++++++369999999
4676/MainThread: /tmp/aaa1516530862947.71075----369999999
4680/MainThread: /tmp/aaa1516530862988.65973----369999999
2018-01-21 18:34:35.165034: 4676/MainThread:start worker: index=126
2018-01-21 18:34:35.173142: 4680/MainThread:start worker: index=127
4675/MainThread: /tmp/aaa1516530862978.17228----369999999
2018-01-21 18:34:35.312469: 4675/MainThread:start worker: index=128
done: 369999999
2018-01-21 18:34:35.563113 - 2018-01-21 18:34:21.483487: pid(4671/done_worker):done_callback: index=117, takes(0:00:14.079626, 0:00:12.532651, -1 day, 23:59:58.720822, 0:00:02.826153)
done_callback
/tmp/aaa1516530862947.71075++++++369999999
done: 369999999
2018-01-21 18:34:36.444812 - 2018-01-21 18:34:22.083625: pid(4671/done_worker):done_callback: index=118, takes(0:00:14.361187, 0:00:13.026874, 0:00:00.476627, 0:00:00.857686)
done_callback
/tmp/aaa1516530862988.65973++++++369999999
done: 369999999
2018-01-21 18:34:37.632338 - 2018-01-21 18:34:22.181960: pid(4671/done_worker):done_callback: index=120, takes(0:00:15.450378, 0:00:12.950711, 0:00:01.342582, 0:00:01.157085)
done_callback
/tmp/aaa1516530862978.17228++++++369999999
done: 369999999
2018-01-21 18:34:38.944739 - 2018-01-21 18:34:22.175776: pid(4671/done_worker):done_callback: index=119, takes(0:00:16.768963, 0:00:13.082986, 0:00:02.404102, 0:00:01.281875)
done_callback
4681/MainThread: /tmp/aaa1516530867066.83715----369999999
2018-01-21 18:34:40.997301: 4681/MainThread:start worker: index=129
/tmp/aaa1516530867066.83715++++++369999999
done: 369999999
2018-01-21 18:34:42.211733 - 2018-01-21 18:34:26.129288: pid(4671/done_worker):done_callback: index=121, takes(0:00:16.082445, 0:00:14.818607, -1 day, 23:59:58.027099, 0:00:03.236739)
done_callback
4674/MainThread: /tmp/aaa1516530870095.57744----369999999
2018-01-21 18:34:44.250236: 4674/MainThread:start worker: index=130