python - cProfile出卖了我吗？

我想知道为什么我的基于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毫秒，而protobuf仅消耗约250毫秒。

但这不是真的！

如果我忽略了protobuf部分，则同一进程在同一系统上仅消耗约1350 ms（-65％）。（我没有添加仅pyzmq脚本，但是您可以发送几个字节而不是序列化的数据）

这些额外的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; }

最佳答案

您要测量的是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（）用作计时器函数，则统计信息将显示sleep函数使用大部分时间。

关于python - cProfile出卖了我吗？，我们在Stack Overflow上找到一个类似的问题：https://stackoverflow.com/questions/29950985/

Protobuf

python - cProfile出卖了我吗？