Skip to content

在guardedWait超时后可能导致metrics日志、request log、slow log等的发送请求耗时计算不准确 #4515

@JianhuaGong

Description

@JianhuaGong

在使用Java-Chassis 2.x版本提供的 request log 功能, %D 占位符打印的请求耗时可能是一个非常大的值, 耗时达到天级甚至几十天

####requestlog####: 10.93.135.178 rest - - Thu, 08 Aug 2024 20:12:40 CST "GET /provider/sayHello HTTP/2.0" 408 3026782406

根据Java-Chassis的源代码

  public void appendClientFormattedItem(InvocationFinishEvent finishEvent, StringBuilder builder) {
    builder.append((finishEvent.getInvocation().getInvocationStageTrace().getFinish() -
        finishEvent.getInvocation().getInvocationStageTrace().getStartSend()) / 1000_000);
  }

其统计请求耗时需要的计时点为startSend和finish.

由于 Java-Chassis 的全链路超时机制统计的耗时代码范围比旧版本的业务请求耗时要广, 导致 Java-Chassis 调用流程可能还没走到startSend赋值的位置, guardedWait等待锁就超时异常了. 此时只有finish有赋值, 而startSend没有赋值, 两者相减就会得到一个特别大的差值.

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions