Python多进程脚本中打印时间返回负值

Question

在Ubuntu 14上运行，使用的是Python 2.7.6

我简化了脚本来展示我的问题：

import time
import multiprocessing

data = range(1, 3)
start_time = time.clock()


def lol():
    for i in data:
        print time.clock() - start_time, "lol seconds"


def worker(n):
    print time.clock() - start_time, "multiprocesor seconds"


def mp_handler():
    p = multiprocessing.Pool(1)
    p.map(worker, data)

if __name__ == '__main__':
    lol()
    mp_handler()

这是输出结果：

8e-06 lol seconds
6.9e-05 lol seconds
-0.030019 multiprocesor seconds
-0.029907 multiprocesor seconds

    Process finished with exit code 0

使用 time.time() 可以得到非负的值（这里有个链接 计时器显示负时间），但我很好奇在Python的 multiprocessing 模块中，使用 time.clock() 和从CPU读取时间时，究竟出了什么问题。

Answer 1

为了给Bakuriu上面精彩的回答增加一个简洁的Python 3示例，你可以使用以下方法来获取一个与子进程无关的全局计时器：

import multiprocessing as mp
import time

# create iterable
iterable = range(4)

# adds three to the given element
def add_3(num):
    a = num + 3
    return a

# multiprocessing attempt
def main():
    pool = mp.Pool(2)
    results = pool.map(add_3, iterable)    
    return results

if __name__ == "__main__":  #Required not to spawn deviant children    
    start=time.time()

    results = main()
    print(list(results))

    elapsed = (time.time() - start)  
    print("\n","time elapsed is :", elapsed)

需要注意的是，如果我们使用的是time.process_time()而不是time.time()，那么结果就会不如预期。

Answer 2

multiprocessing 是用来创建新进程的，而在Linux上，time.clock()的意思和C语言里的clock()是一样的：

返回的值是到目前为止使用的CPU时间，以clock_t的形式表示；

所以，当一个进程启动时，clock返回的值会从0开始。不过你的代码是用父进程的start_time来判断子进程花费的时间，这显然是不对的，因为子进程的CPU时间是会重置的。

clock()函数只有在处理一个进程时才有意义，因为它返回的值是那个进程所花费的CPU时间。子进程的时间是不被考虑在内的。

而time()函数则使用的是系统级的时钟，因此可以在不同进程之间使用（尽管它不是单调的，所以如果在事件发生期间有人更改了系统时间，它可能会返回错误的结果）。

从一个正在运行的Python实例中分叉出一个新进程，通常比从头开始启动一个新进程要快，因此start_time几乎总是比time.clock()返回的值要大。要考虑到，父进程还需要读取你的文件、进行导入，这可能需要读取其他.py文件、搜索目录等等。而被分叉的子进程就不需要做这些了。

---

下面是一个示例代码，展示了time.clock()的返回值是如何重置为0的：

from __future__ import print_function

import time
import multiprocessing

data = range(1, 3)
start_time = time.clock()


def lol():
    for i in data:
        t = time.clock()
        print('t: ', t, end='\t')
        print(t - start_time, "lol seconds")


def worker(n):
    t = time.clock()
    print('t: ', t, end='\t')
    print(t - start_time, "multiprocesor seconds")


def mp_handler():
    p = multiprocessing.Pool(1)
    p.map(worker, data)

if __name__ == '__main__':
    print('start_time', start_time)
    lol()
    mp_handler()

结果：

$python ./testing.py 
start_time 0.020721
t:  0.020779    5.8e-05 lol seconds
t:  0.020804    8.3e-05 lol seconds
t:  0.001036    -0.019685 multiprocesor seconds
t:  0.001166    -0.019555 multiprocesor seconds

注意在lol的情况下，t是单调的，而在另一个情况下则回到了0.001。