curl / Mailing Lists / curl-library / Single Mail

curl-library

Re: curl_multi_perform sometimes does not return while its threadus es1 00% cpu resources

From: <h9791521_at_docomo.ne.jp>
Date: Tue, 25 Dec 2018 19:03:48 +0900

sorry i made a mistake, please ignore the previous email, and please read this instead.

Hello all,

We finally got the detailed log when the event occurred.
As you see, since time_t is defined to unsigned type in 32 bit Windows, the evaluation failed in the specific case.
https://github.com/curl/curl/issues/2004
I think this guy already pointed out this issue in 7.55, but missed the following point.
As I'm not familir with libcurl, I will use compare macro that is used in Curl_splaygetbest().
Do you think this workaround will work?

add_next_timeout(2599)#### ttime(12207 998000) tnow(12208 003000) ####
add_next_timeout(2603) sizeofdiff : 8
add_next_timeout(2609) diff : fffffffb ffffffff ffffffff ffffffff ffffffe7 03 00 00

nodetime(12207 99800) now(12208 003000)

diff = Curl_timediff(node->time, now);

timediff_t Curl_timediff(struct curltime newer, struct curltime older)
{
 timediff_t diff = newer.tv_sec-older.tv_sec;
 if(diff >= (TIME_MAX/1000))
   return TIME_MAX;
 else if(diff <= (TIME_MIN/1000))
   return TIME_MIN;
 return diff * 1000 + (newer.tv_usec-older.tv_usec)/1000;
}

struct curltime {
 time_t tv_sec; /* seconds */
 int tv_usec; /* microseconds */
};


return -1 * 1000 + (998000 - 003000)/1000;
Expected result: -5

In reality, time_t is defined to unsigned type in 32 bit Windows
return 0xFFFFFFFF * 1000 + (998000 - 003000)/1000;
Actual result: 4294967295000 + 995 =0x3e7fffffffb


timediff_t Curl_timediff(struct curltime newer, struct curltime older)
{
 timediff_t diff = newer.tv_sec-older.tv_sec;



iPhoneから送信

2018/12/25 18:24、"h9791521_at_docomo.ne.jp" <h9791521_at_docomo.ne.jp>のメール:

> Hello all,
>
> I finally got the detailed log when the event occurred.
> As you see, since time_t is defined to unsigned type in 32 bit Windows, the evaluation failed in the specific case.
> https://github.com/curl/curl/issues/2004
> I think this guy already pointed out this issue in 7.55, but missed the following point.
> As I'm not familir with libcurl, I will use compare macro that is used in Curl_splaygetbest() for the same purpose.
> Do you think this compare to macro should work?
>
> add_next_timeout(2599)#### ttime(12207 998000) tnow(12208 003000) ####
> add_next_timeout(2603) sizeofdiff : 8
> add_next_timeout(2609) diff : fffffffb ffffffff ffffffff ffffffff ffffffe7 03 00 00
>
> nodetime(999 12207) now(998000 12208)
> diff = Curl_timediff(node->time, now);
>
> timediff_t Curl_timediff(struct curltime newer, struct curltime older)
> {
> timediff_t diff = newer.tv_sec-older.tv_sec;
> if(diff >= (TIME_MAX/1000))
> return TIME_MAX;
> else if(diff <= (TIME_MIN/1000))
> return TIME_MIN;
> return diff * 1000 + (newer.tv_usec-older.tv_usec)/1000;
> }
>
> struct curltime {
> time_t tv_sec; /* seconds */
> int tv_usec; /* microseconds */
> };
>
>
> return -1 * 1000 + (998000 - 003000)/1000;
> Expected result: -5
>
> In reality, time_t is defined to unsigned type in 32 bit Windows
> return 0xFFFFFFFF * 1000 + (998000 - 003000)/1000;
> Actual result: 4294967295000 + 995 =0x3e7fffffffb
>
>
> timediff_t Curl_timediff(struct curltime newer, struct curltime older)
> {
> timediff_t diff = newer.tv_sec-older.tv_sec;
>
>
>
>
> 2018/12/19 18:55、"h9791521_at_docomo.ne.jp" <h9791521_at_docomo.ne.jp>のメール:
>
>> Hello all
>>
>> I inserted the log in multi.c to find why the endless loop happened, and after many executions, I finally got the following log.
>> Could somebody tell me what's going on?
>> Or tell me what kind of logs I should add more
>> Apparenetly, timetree got corrupt,which caused calling add_next_timeout() endlessly.
>>
>> You can see in the end "t = 00924960" kept happening endlessly, which caused thread 25C8039A to consume the cpu usage 100%.
>>
>> 12:30:59.300 TID:36DB014E <libcurl>[Debug]Curl_expire_clear(3050) data->state.timenode = 00E94960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00E94960, data->state.timenode.samep = 00E94960, data->state.timenode.key.tv_sec = 403
>> 12:30:59.300 TID:36DB014E <libcurl>[Debug]Curl_expire_clear(3051) call Curl_splayremovebyaddr
>> 12:31:51.934 TID:3C010402 <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00EA4960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:31:51.934 TID:3C010402 <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:31:51.934 TID:3C010402 <libcurl>[Debug]curl_multi_perform(2196) t = 00EA4960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00EA4960, t->samep = 00EA4960, t->key.tv_sec = 381
>> 12:31:51.934 TID:3C010402 <libcurl>[Debug]curl_multi_perform(2196) t = 00EA4960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00EA4960, t->samep = 00EA4960, t->key.tv_sec = 381
>> 12:31:52.106 TID:3C010402 <libcurl>[Debug]curl_multi_perform(2196) t = 00EA4960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00EA4960, t->samep = 00EA4960, t->key.tv_sec = 471
>> 12:31:53.400 TID:285A0256 <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00924960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:31:53.400 TID:285A0256 <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:31:53.400 TID:285A0256 <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 382
>> 12:31:53.463 TID:285A0256 <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 383
>> 12:31:53.572 TID:285A0256 <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 383
>> 12:31:55.007 TID:3D9105DE <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00974960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:31:55.007 TID:3DA701F6 <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00994960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:31:55.007 TID:3D9105DE <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:31:55.023 TID:3DAB0236 <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 009B4960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:31:55.023 TID:3DA701F6 <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:31:55.023 TID:3DAB0236 <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:31:55.023 TID:3D9105DE <libcurl>[Debug]curl_multi_perform(2196) t = 00974960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00974960, t->samep = 00974960, t->key.tv_sec = 383
>> 12:31:55.023 TID:3DA701F6 <libcurl>[Debug]curl_multi_perform(2196) t = 00994960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00994960, t->samep = 00994960, t->key.tv_sec = 383
>> 12:31:55.038 TID:3DAB0236 <libcurl>[Debug]curl_multi_perform(2196) t = 009B4960, t->smaller = 00000000, t->larger = 00000000, t->samen = 009B4960, t->samep = 009B4960, t->key.tv_sec = 383
>> 12:31:55.038 TID:3D9105DE <libcurl>[Debug]curl_multi_perform(2196) t = 00974960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00974960, t->samep = 00974960, t->key.tv_sec = 383
>> 12:31:55.038 TID:3DA701F6 <libcurl>[Debug]curl_multi_perform(2196) t = 00994960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00994960, t->samep = 00994960, t->key.tv_sec = 383
>> 12:31:55.038 TID:3DAB0236 <libcurl>[Debug]curl_multi_perform(2196) t = 009B4960, t->smaller = 00000000, t->larger = 00000000, t->samen = 009B4960, t->samep = 009B4960, t->key.tv_sec = 383
>> 12:31:55.194 TID:3D9105DE <libcurl>[Debug]curl_multi_perform(2196) t = 00974960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00974960, t->samep = 00974960, t->key.tv_sec = 383
>> 12:31:55.210 TID:3DAB0236 <libcurl>[Debug]curl_multi_perform(2196) t = 009B4960, t->smaller = 00000000, t->larger = 00000000, t->samen = 009B4960, t->samep = 009B4960, t->key.tv_sec = 383
>> 12:31:55.210 TID:3DA701F6 <libcurl>[Debug]curl_multi_perform(2196) t = 00994960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00994960, t->samep = 00994960, t->key.tv_sec = 383
>> 12:31:56.037 TID:255A02FE <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00A44960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:31:56.037 TID:255A02FE <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:31:56.037 TID:255A02FE <libcurl>[Debug]curl_multi_perform(2196) t = 00A44960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00A44960, t->samep = 00A44960, t->key.tv_sec = 384
>> 12:31:56.037 TID:255A02FE <libcurl>[Debug]curl_multi_perform(2196) t = 00A44960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00A44960, t->samep = 00A44960, t->key.tv_sec = 385
>> 12:31:56.068 TID:255A02FE <libcurl>[Debug]curl_multi_perform(2196) t = 00A44960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00A44960, t->samep = 00A44960, t->key.tv_sec = 385
>> 12:31:56.567 TID:3C010402 <libcurl>[Debug]Curl_expire_clear(3050) data->state.timenode = 00EA4960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00EA4960, data->state.timenode.samep = 00EA4960, data->state.timenode.key.tv_sec = 471
>> 12:31:56.583 TID:3C010402 <libcurl>[Debug]Curl_expire_clear(3051) call Curl_splayremovebyaddr
>> 12:32:03.260 TID:35570316<libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00944960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:03.260 TID:35570316<libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:03.260 TID:35570316<libcurl>[Debug]curl_multi_perform(2196) t = 00944960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00944960, t->samep = 00944960, t->key.tv_sec = 392
>> 12:32:03.306 TID:35570316<libcurl>[Debug]curl_multi_perform(2196) t = 00944960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00944960, t->samep = 00944960, t->key.tv_sec = 392
>> 12:32:03.431 TID:3445014A <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00994960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:03.431 TID:3445014A <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:03.431 TID:3445014A <libcurl>[Debug]curl_multi_perform(2196) t = 00994960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00994960, t->samep = 00994960, t->key.tv_sec = 392
>> 12:32:03.431 TID:3445014A <libcurl>[Debug]curl_multi_perform(2196) t = 00994960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00994960, t->samep = 00994960, t->key.tv_sec = 392
>> 12:32:03.650 TID:0E9402BA <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00934960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:03.665 TID:0E9402BA <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:03.665 TID:0E9402BA <libcurl>[Debug]curl_multi_perform(2196) t = 00934960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00934960, t->samep = 00934960, t->key.tv_sec = 392
>> 12:32:03.665 TID:0E9402BA <libcurl>[Debug]curl_multi_perform(2196) t = 00934960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00934960, t->samep = 00934960, t->key.tv_sec = 392
>> 12:32:03.759 TID:35570316<libcurl>[Debug]curl_multi_perform(2196) t = 00944960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00944960, t->samep = 00944960, t->key.tv_sec = 392
>> 12:32:03.821 TID:3445014A <libcurl>[Debug]curl_multi_perform(2196) t = 00994960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00994960, t->samep = 00994960, t->key.tv_sec = 392
>> 12:32:03.852 TID:0E9402BA <libcurl>[Debug]curl_multi_perform(2196) t = 00934960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00934960, t->samep = 00934960, t->key.tv_sec = 392
>> 12:32:09.546 TID:3D91064A <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00924960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:09.562 TID:3D91064A <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:09.562 TID:3D91064A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 399
>> 12:32:09.562 TID:3D91064A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 399
>> 12:32:09.671 TID:3D91064A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 399
>> 12:32:14.882 TID:3D6C04B2 <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00924960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:14.882 TID:3D6C04B2 <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:14.882 TID:3D6C04B2 <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 404
>> 12:32:14.882 TID:3D6C04B2 <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 404
>> 12:32:15.038 TID:3D6C04B2 <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 404
>> 12:32:18.454 TID:3D9301EA <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00974960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:18.454 TID:3D9301EA <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:18.454 TID:3D9301EA <libcurl>[Debug]Curl_expire(2987) data->state->timenode = 00974960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00974960, data->state.timenode.samep = 00974960, data->state.timenode.key.tv_sec = 408
>> 12:32:18.454 TID:3D9301EA <libcurl>[Debug]Curl_expire(2988) call Curl_splayremovebyaddr
>> 12:32:18.454 TID:3D9301EA <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00974960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00974960, data->state.timenode.samep = 00974960, data->state.timenode.key.tv_sec = 408
>> 12:32:18.454 TID:3D9301EA <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:18.454 TID:3D9301EA <libcurl>[Debug]curl_multi_perform(2196) t = 00974960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00974960, t->samep = 00974960, t->key.tv_sec = 408
>> 12:32:18.626 TID:3D9301EA <libcurl>[Debug]curl_multi_perform(2196) t = 00974960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00974960, t->samep = 00974960, t->key.tv_sec = 408
>> 12:32:20.919 TID:3CE905E6 <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00924960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:20.934 TID:3CE905E6 <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:20.934 TID:3CE905E6 <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 410
>> 12:32:20.934 TID:3CE905E6 <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 410
>> 12:32:21.044 TID:3CE905E6 <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 410
>> 12:32:22.604 TID:3D770116 <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00974960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:22.604 TID:3D770116 <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:22.619 TID:3D770116 <libcurl>[Debug]curl_multi_perform(2196) t = 00974960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00974960, t->samep = 00974960, t->key.tv_sec = 412
>> 12:32:22.619 TID:3D770116 <libcurl>[Debug]curl_multi_perform(2196) t = 00974960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00974960, t->samep = 00974960, t->key.tv_sec = 412
>> 12:32:22.760 TID:3D770116 <libcurl>[Debug]curl_multi_perform(2196) t = 00974960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00974960, t->samep = 00974960, t->key.tv_sec = 412
>> 12:32:26.722 TID:3CF600CA <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00924960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:26.722 TID:3CF600CA <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:26.722 TID:3CF600CA <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 416
>> 12:32:26.722 TID:3CF600CA <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 416
>> 12:32:26.894 TID:3CF600CA <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 416
>> 12:32:27.128 TID:3CC206EE <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00934960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:27.128 TID:3CC206EE <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:27.128 TID:3CC206EE <libcurl>[Debug]Curl_expire(2987) data->state->timenode = 00934960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00934960, data->state.timenode.samep = 00934960, data->state.timenode.key.tv_sec = 416
>> 12:32:27.128 TID:3CC206EE <libcurl>[Debug]Curl_expire(2988) call Curl_splayremovebyaddr
>> 12:32:27.128 TID:3CC206EE <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00934960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00934960, data->state.timenode.samep = 00934960, data->state.timenode.key.tv_sec = 416
>> 12:32:27.143 TID:3CC206EE <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:27.143 TID:3CC206EE <libcurl>[Debug]curl_multi_perform(2196) t = 00934960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00934960, t->samep = 00934960, t->key.tv_sec = 416
>> 12:32:27.206 TID:3CC206EE <libcurl>[Debug]curl_multi_perform(2196) t = 00934960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00934960, t->samep = 00934960, t->key.tv_sec = 416
>> 12:32:31.449 TID:3CD4015E <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00934960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:31.449 TID:3CD4015E <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:31.449 TID:3CD4015E <libcurl>[Debug]curl_multi_perform(2196) t = 00934960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00934960, t->samep = 00934960, t->key.tv_sec = 420
>> 12:32:31.464 TID:3CD4015E <libcurl>[Debug]curl_multi_perform(2196) t = 00934960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00934960, t->samep = 00934960, t->key.tv_sec = 420
>> 12:32:31.808 TID:3CD4015E <libcurl>[Debug]curl_multi_perform(2196) t = 00934960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00934960, t->samep = 00934960, t->key.tv_sec = 420
>> 12:32:33.929 TID:25C8039A <libcurl>[Debug]Curl_expire(3007) data->state.timenode = 00924960, data->state.timenode.smaller = 00000000, data->state.timenode.larger = 00000000, data->state.timenode.samen = 00000000, data->state.timenode.samep = 00000000, data->state.timenode.key.tv_sec = 0
>> 12:32:33.929 TID:25C8039A <libcurl>[Debug]Curl_expire(3008) call Curl_splayinsert
>> 12:32:33.929 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> 12:32:33.945 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> 12:32:34.023 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> 12:32:34.023 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> 12:32:34.085 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> 12:32:34.085 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> 12:32:34.085 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> 12:32:34.085 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> 12:32:34.085 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> 12:32:34.085 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> 12:32:34.101 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> 12:32:34.101 TID:25C8039A <libcurl>[Debug]curl_multi_perform(2196) t = 00924960, t->smaller = 00000000, t->larger = 00000000, t->samen = 00924960, t->samep = 00924960, t->key.tv_sec = 421
>> "t = 00924960" kept happening endlessly, which caused thread 25C8039A to consume the cpu usage 100%.
>>
>> The following are where I added the log.
>>
>> CURLMcode curl_multi_perform(struct Curl_multi *multi, int *running_handles)
>>
>> do {
>> multi->timetree = Curl_splaygetbest(now, multi->timetree, &t);
>> if(t){
>> /* the removed may have another timeout in queue */
>> (void)add_next_timeout(now, multi, t->payload);
>> DEBUGLOG("t = %p, t->smaller = %p, t->larger = %p, t->samen = %p, t->samep = %p, t->key.tv_sec = %ld \n",
>> t, t->smaller, t->larger, t->samen, t->samep, t->key.tv_sec );
>> }
>>
>> } while(t);
>>
>> void Curl_expire(struct Curl_easy *data, time_t milli, expire_id id)
>>
>> /* Indicate that we are in the splay tree and insert the new timer expiry
>> value since it is our local minimum. */
>> *nowp = set;
>> data->state.timenode.payload = data;
>>
>> DEBUGLOG("data->state.timenode = %p, data->state.timenode.smaller = %p, data->state.timenode.larger = %p, data->state.timenode.samen = %p, data->state.timenode.samep = %p, data->state.timenode.key.tv_sec = %ld \n ",
>> &data->state.timenode, data->state.timenode.smaller, data->state.timenode.larger, data->state.timenode.samen, data->state.timenode.samep, data->state.timenode.key.tv_sec );
>> DEBUGLOG(" call Curl_splayinsert\n ");
>>
>> multi->timetree = Curl_splayinsert(*nowp, multi->timetree,
>> &data->state.timenode);
>> }
>>
>>
>>
>> 2018/12/14 16:23、Daniel Stenberg <daniel_at_haxx.se>のメール:
>>
>>>> On Thu, 13 Dec 2018, "h9791521_at_docomo.ne.jp" wrote:
>>>>
>>>> I confirmed that time_t is defined as unsigned long in windows, which I
>>>> think is equivalent to HAVE TIME T UNSIGNED.
>>>
>>> Please show me details and describe exactly where you found this.
>>>
>>>> Regarding an example source code, it's hard for me to pick up and post them
>>>> and it(= "compare(i, t->key) never gets negative") occurs once in thousand
>>>> times after simply calling curl_easy_perform()
>>>
>>> I understand that I'm asking for something that might not be easy to create,
>>> but it is even harder for us outside of your project to understand or
>>> reproduce this issue.
>>>
>>> Until we can reproduce or understand it, it *could* also just be your program
>>> running amok somehow. libcurl is after all used by a large amount of users all
>>> over that don't get this problem.
>>>
>>>> I don't use libcurl multi-threaded, I mean, there are many other threads in
>>>> this process, but the only one thread calls curl_easy_perform().
>>>
>>> Also the only thread doing libcurl calls?
>>>
>>> --
>>>
>>> / daniel.haxx.se

-------------------------------------------------------------------
Unsubscribe: https://cool.haxx.se/list/listinfo/curl-library
Etiquette: https://curl.haxx.se/mail/etiquette.html
Received on 2018-12-25