cProfile在背叛我吗？

Question

我想知道为什么我的基于pyzmq和protobuf的消息传递要比预期慢得多，所以我使用cProfile来检查您在文章末尾找到的脚本。

protoc --python_out=. rpc.proto
python -m cProfile -o rpc.pstats ./test_rpc.py

返回

3.604 sec for 10000 messages, 360.41us/m, 2774 m/s

和

python -m pstats rpc.pstats 
rpc.pstats% sort tottime
rpc.pstats% stats 10

提供给我(仅供客户端进程使用)：

         619163 function calls (618374 primitive calls) in 3.779 seconds

   Ordered by: internal time
   List reduced from 580 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    10002    2.658    0.000    2.658    0.000 {method 'recv' of 'zmq.backend.cython.socket.Socket' objects}
    10002    0.088    0.000    0.088    0.000 {method 'send' of 'zmq.backend.cython.socket.Socket' objects}
    10001    0.060    0.000    3.654    0.000 ./test_rpc.py:36(rpc_set)
    10002    0.058    0.000    3.457    0.000 ./test_rpc.py:32(zmq_reply)
    80016    0.056    0.000    0.056    0.000 {method 'write' of 'cStringIO.StringO' objects}
    10002    0.056    0.000    0.424    0.000 /usr/lib/python2.7/site-packages/google/protobuf/internal/python_message.py:781(InternalSerialize)
    30004    0.054    0.000    0.137    0.000 /usr/lib/python2.7/site-packages/google/protobuf/internal/python_message.py:453(setter)
    20002    0.051    0.000    0.058    0.000 /usr/lib/python2.7/site-packages/google/protobuf/internal/type_checkers.py:113(CheckValue)
    10002    0.050    0.000    0.055    0.000 /usr/lib/python2.7/site-packages/google/protobuf/internal/python_message.py:839(IsInitialized)
    10002    0.050    0.000    0.148    0.000 /usr/lib/python2.7/site-packages/google/protobuf/internal/python_message.py:577(ListFields)

...

奇怪的是:来自recv()/send()的pyzmq似乎消耗了大约2700 ms，而protobuf只消耗了250 ms。

但那不是真的！

如果我离开protobuf部分，相同的进程只消耗相同系统上的1350 ms (-65%)。(我没有添加pyzmq-only脚本，但是您可以发送几个字节而不是序列化的数据)

这些额外的65%归因于几乎100%的pyzmq，它实际上是由protobuf消费的。

问题：这是怎么回事？在这种情况下，我如何能够以指向protobuf而不是pyzmq的方式来分析我的脚本呢？

为了重现日期，您必须安装protobuf-python和python-zmq。下面是用于这个实验的脚本：

test_rpc.py：

import sys
import time
import threading
import subprocess
import zmq

import rpc_pb2  # must be generated first

if '--server' in sys.argv:
    print('zmq_protobuf_rpc_server')
    context = zmq.Context()
    socket = context.socket(zmq.REP)
    socket.bind("tcp://*:5556")

    request = rpc_pb2.rpc_request()
    reply = rpc_pb2.rpc_reply()

    while True:

        request.ParseFromString(socket.recv())
        if request.type == rpc_pb2.rpc_request.SET:
            value = request.value
        elif request.type == rpc_pb2.rpc_request.GET:
            reply.value = "value"
        socket.send(reply.SerializeToString())
        if request.type == rpc_pb2.rpc_request.QUIT:
            break

else:
    def zmq_reply(req_msg, rep_msg, socket):
        socket.send(req_msg.SerializeToString())
        rep_msg.ParseFromString(socket.recv())

    def rpc_set(req_msg, rep_msg, socket, name, value):
        req_msg.type = rpc_pb2.rpc_request.SET
        req_msg.name = name
        req_msg.value = value
        zmq_reply(req_msg, rep_msg, socket)

    def rpc_get(req_msg, rep_msg, socket, name):
        req_msg.type = rpc_pb2.rpc_request.GET
        req_msg.name = name
        zmq_reply(req_msg, rep_msg, socket)
        return rep_msg.value

    print('zmq_protobuf_rpc')
    p = subprocess.Popen([sys.executable, '-u', __file__, '--server'])
    context = zmq.Context()
    socket = context.socket(zmq.REQ)
    socket.connect("tcp://127.0.0.1:5556")  # IPC would be a bit faster

    request = rpc_pb2.rpc_request()
    reply = rpc_pb2.rpc_reply()

    # wait for the server to be responsive
    rpc_set(request, reply, socket, 'hello', 'hello')

    N = 10000

    t = time.time()
    for i in range(N):
        rpc_set(request, reply, socket, 'name', str(i))
    t = time.time() - t
    print("%.3f sec for %d messages, %.2fus/m, %d m/s" 
          % (t, N, t / N * 1000000, N/t))

    request.type = rpc_pb2.rpc_request.QUIT
    zmq_reply(request, reply, socket)

    p.wait()

rpc.proto：

package rpc;

message rpc_request {
    enum RpcType {GET = 0; SET = 1; QUIT = 2; }
    required RpcType type = 1;
    required string name = 2;
    optional string value = 3; }

message rpc_reply {
    optional string value = 3; }

Answer 1

您希望度量的是process_time，而不是默认测量的system_time。这是通过为分析器使用自定义计时器函数来完成的，例如time.process_time()。

示例：

import cProfile
import time
import pstats
import io

pr = cProfile.Profile(time.process_time)

pr.enable()

time.sleep(1)
for i in range(0, 1000):
    print("hello world")
time.sleep(1)
pr.disable()

s = io.StringIO()
sortby = 'cumulative'
ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
ps.print_stats()
print(s.getvalue())

打印函数消耗了大部分process_time，而统计数据将显示这一点。如果不将time.process_time()作为计时器函数传递，那么stats将显示睡眠函数大部分时间使用。