square / okhttp

Square’s meticulous HTTP client for the JVM, Android, and GraalVM.
https://square.github.io/okhttp/
Apache License 2.0
45.85k stars 9.16k forks source link

🙉Why is the SSE event callback slow? #8541

Closed aa563011992 closed 1 month ago

aa563011992 commented 1 month ago

2024-09-21 09:21:21.513 7529-7984 AliSseManager E --> POST https://dashscope.aliyuncs.com/api/v1/services/aigc/text-generation/generation h2 2024-09-21 09:21:21.513 7529-7984 AliSseManager E Authorization: xxx 2024-09-21 09:21:21.513 7529-7984 AliSseManager E Accept-Encoding: 2024-09-21 09:21:21.513 7529-7984 AliSseManager E Accept: text/event-stream 2024-09-21 09:21:21.513 7529-7984 AliSseManager E Cache-Control: no-cache 2024-09-21 09:21:21.513 7529-7984 AliSseManager E Content-Type: application/json; charset=utf-8 2024-09-21 09:21:21.513 7529-7984 AliSseManager E Content-Length: 640 2024-09-21 09:21:21.513 7529-7984 AliSseManager E Host: dashscope.aliyuncs.com 2024-09-21 09:21:21.513 7529-7984 AliSseManager E Connection: Keep-Alive 2024-09-21 09:21:21.513 7529-7984 AliSseManager E User-Agent: okhttp/4.12.0 2024-09-21 09:21:21.513 7529-7984 AliSseManager E
2024-09-21 09:21:21.513 7529-7984 AliSseManager E {"input":{"messages":[{"content":"You are a helpful assistant.","role":"system"},{"content":"如何讨薪","role":"user"}],"session_id":"32bc81f7-f2d8-4665-8e7b-a132645062f3"},"model":"farui-plus"} 2024-09-21 09:21:21.513 7529-7984 AliSseManager E --> END POST (640-byte body) 2024-09-21 09:21:21.842 7529-7984 AliSseManager E <-- 200 https://dashscope.aliyuncs.com/api/v1/services/aigc/text-generation/generation (328ms) 2024-09-21 09:21:21.842 7529-7984 AliSseManager E eagleeye-traceid: d81c3c93fc8303e426f8268942a1b820 2024-09-21 09:21:21.842 7529-7984 AliSseManager E x-request-id: c12310fe-3fb6-976a-9509-5641a77de05c 2024-09-21 09:21:21.842 7529-7984 AliSseManager E content-type: text/event-stream;charset=UTF-8 2024-09-21 09:21:21.842 7529-7984 AliSseManager E x-dashscope-call-gateway: true 2024-09-21 09:21:21.842 7529-7984 AliSseManager E x-dashscope-timeout: 180 2024-09-21 09:21:21.843 7529-7984 AliSseManager E x-dashscope-finished: false 2024-09-21 09:21:21.843 7529-7984 AliSseManager E req-cost-time: 213 2024-09-21 09:21:21.843 7529-7984 AliSseManager E req-arrive-time: 1726881680941 2024-09-21 09:21:21.843 7529-7984 AliSseManager E resp-start-time: 1726881681155 2024-09-21 09:21:21.843 7529-7984 AliSseManager E x-envoy-upstream-service-time: 207 2024-09-21 09:21:21.843 7529-7984 AliSseManager E set-cookie: acw_tc=c12310fe-3fb6-976a-9509-5641a77de05c4050d03f865c45770f98d3d1707293b2;path=/;HttpOnly;Max-Age=1800 2024-09-21 09:21:21.843 7529-7984 AliSseManager E date: Sat, 21 Sep 2024 01:21:20 GMT 2024-09-21 09:21:21.843 7529-7984 AliSseManager E server: istio-envoy 2024-09-21 09:21:28.305 7529-7984 AliSseManager E
2024-09-21 09:21:28.306 7529-7984 AliSseManager E id:1
event:result :HTTP_STATUS/200 data:{"output":{"finish_reason":"null","text":"你好"}

As you see,The first event took 7 seconds to receive。

aa563011992 commented 1 month ago

And although the events are returned in batches, there is no time interval in between

aa563011992 commented 1 month ago

2024-09-21 09:39:48.500 15386-15527 AliSseManager I onOpen 2024-09-21 09:39:48.507 15386-15527 AliSseManager I onEvent:{"output":{"finish_reason":"null","text":"你好"},"usage":{"total_tokens":74,"input_tokens":73,"output_tokens":1},"request_id":"3c635115-e813-9f14-b5a9-c160c9ba0e39"} 2024-09-21 09:39:48.508 15386-15527 AliSseManager I onEvent:{"output":{"finish_reason":"null","text":"你好!"},"usage":{"total_tokens":75,"input_tokens":73,"output_tokens":2},"request_id":"3c635115-e813-9f14-b5a9-c160c9ba0e39"} 2024-09-21 09:39:48.508 15386-15527 AliSseManager I onEvent:{"output":{"finish_reason":"null","text":"你好!我是"},"usage":{"total_tokens":76,"input_tokens":73,"output_tokens":3},"request_id":"3c635115-e813-9f14-b5a9-c160c9ba0e39"}

aa563011992 commented 1 month ago

I have found the reason: if (DEBUG) { addNetworkInterceptor(loggingInterceptor) }