如何查看Azure Durable Functions的请求处理与响应时长

一、使用Application Insights日志查询 #

前提条件 #

确保你的Azure Functions已启用Application Insights集成（创建Function App时默认开启，也可后续在Azure门户中配置）。

查询HTTP请求总响应时长 #

打开Application Insights的「日志」页面，执行以下Kusto查询，获取客户端HTTP函数的完整响应时长：

requests
| where name == "POST /api/orchestrators/client_function" // 匹配你的HTTP路由
| project 时间戳=timestamp, 请求ID=id, 函数名称=name, 响应时长(毫秒)=duration, 是否成功=success, 状态码=resultCode
| sort by timestamp desc

duration字段即为整个HTTP请求从接收至返回响应的总时长（单位：毫秒）。

查询Orchestrator执行时长 #

Durable Functions会自动向Application Insights发送自定义事件，可通过以下查询获取Orchestrator的运行时长：

customEvents
| where name == "DurableOrchestratorCompleted"
| project 时间戳=timestamp, 实例ID=customDimensions.InstanceId, 运行时长(毫秒)=todouble(customDimensions.DurationMs), 运行状态=customDimensions.RuntimeStatus
| sort by timestamp desc

查询Activity函数执行时长 #

同理，查询Activity函数的执行时长可使用：

customEvents
| where name == "DurableActivityCompleted"
| project 时间戳=timestamp, 实例ID=customDimensions.InstanceId, Activity名称=customDimensions.ActivityName, 运行时长(毫秒)=todouble(customDimensions.DurationMs)
| sort by timestamp desc

二、其他查询方法 #

1. 在代码中手动记录时长并输出 #

记录HTTP请求总时长

修改client_function，添加计时逻辑：

async def client_function(req: func.HttpRequest, client: df.DurableOrchestrationClient) -> func.HttpResponse:
    start_time = time.perf_counter()
    activity = int(req.params.get('activity') or req.get_json().get('activity'))
    size = int(req.params.get('size') or req.get_json().get('size'))

    instance_id = await client.start_new("orchestrator", None, {"activity": activity, "size": size})
    logging.info(f"Started orchestration with ID = '{instance_id}'.")
    await client.wait_for_completion_or_create_check_status_response(req, instance_id)
    status = await client.get_status(instance_id)
    
    # 计算并记录总时长
    total_duration = time.perf_counter() - start_time
    logging.info(f"Request completed for instance {instance_id}, total duration: {total_duration:.4f}s")
    return f"runtime: {status.runtime_status}\n\noutput: {status.output}\nTotal request duration: {total_duration:.4f}s"

记录Orchestrator和Activity的细分时长

在Orchestrator中利用上下文时间戳计算总时长，同时补充Activity的细粒度计时：

def orchestrator(context: df.DurableOrchestrationContext) -> dict:
    orchestrator_start = context.current_utc_datetime
    parameter = context.get_input()
    activity = int(parameter.get("activity"))
    size = int(parameter.get("size"))
    data_size_list, byte_list, time_list = [], [], []
    
    if activity == 1: #DataFrame
        for i in range(2):        
            result  =  yield context.call_activity("activity1", size)
            data_frame = pd.DataFrame.from_dict(result["data"])  # deserialize
            transfer_time  =  time.perf_counter() - result["start"] 
            dict_size = sys.getsizeof(result["data"]) 
            dict_size += sum(map(sys.getsizeof, result["data"].values())) + sum(map(sys.getsizeof, result["data"].keys()))

            data_size_list.append(size)
            byte_list.append(dict_size)
            time_list.append(transfer_time)

    output = {"data-size": data_size_list, "data-byte": byte_list, "transfer-time": time_list}
    result = yield context.call_activity("write_csv", output)
    
    # 计算Orchestrator总时长并记录
    orchestrator_duration = (context.current_utc_datetime - orchestrator_start).total_seconds()
    logging.info(f"Orchestrator {context.instance_id} completed, duration: {orchestrator_duration:.4f}s")
    return {**output, "orchestrator_duration": orchestrator_duration}

2. 利用Durable Functions的状态查询接口 #

通过get_status方法获取实例的创建时间和最后更新时间，直接计算Orchestrator运行时长：

# 在client_function中添加
status = await client.get_status(instance_id)
orchestrator_duration = (status.last_updated_time - status.created_time).total_seconds()
logging.info(f"Orchestrator {instance_id} duration: {orchestrator_duration:.4f}s")

3. 本地开发时查看控制台日志 #

使用Azure Functions Core Tools运行func start，控制台会直接输出每个函数的执行耗时，例如：

Executing 'Functions.client_function' (Reason='This function was programmatically called via the host APIs.', Id=xxxxxx)
Executing 'Functions.orchestrator' (Reason='(null)', Id=yyyyyy)
Executed 'Functions.orchestrator' (Succeeded, Id=yyyyyy, Duration=1500ms)
Executed 'Functions.client_function' (Succeeded, Id=xxxxxx, Duration=1600ms)

内容的提问来源于stack exchange，提问作者TY00