a tricky problem with using events

From: Chengdu Huang <chuang@dont-contact.us>
Date: Mon, 9 Jun 2003 01:58:06 -0400

This mail is a little long but the problem is quite tricky. So please be
patient and bear with me.

I have a tricky problem with the event mechanism of Squid. Basically I
want to do is letting Squid periodically contact an HTTP server and
download some files (about 20KB in sizes) and store them to disk. Since
it's a periodical, scheduling events is the natural choice.

Note that these requests sent to the HTTP server has no client associated.

So my code is like this:
1. add an event by eventAdd("Periodical", routine, data, when, 1);

2. in routine(), construct an http request, a StoreEntry and its mem_obj.
   Call a function doing similar job of fwdStart() but no peer will
   be chosen since the http request goes to a certain server.

3. if a connection is in persistent connection queue, it will be used,
   otherwise a new connection will be opened by comm_open(). close handler,
   timeout handler are set. This is just what fwdConnectStart() does.

4. httpStart() is called.

From this one, the http request goes through normal HTTP request
processing. When the socket receives reply from server, httpReadReply will
be called and so on. Finally it comes to storeComplete() where I can
schedule next occurrence of this event.

The code works! It contacts the HTTP server periodically and files are
swapped to disk etc. But it has a serious problem: some events (NOT all)
takes very long to finish. For example, it can take as long as 2 seconds
for one occurrence of such event with both the Squid and HTTP server are
in the same LAN. As comparison, a normal client request goes through squid
to HTTP server takes less than 10ms. So they're unbelievablly slow.

I traced down the problem by measuring time consumed by each stage from
the beginning of the event till httpReadReply() gets called. I found that
there're two cases for these extremely slow events:
case 1 (total time is 400+ms) :
2003/06/09 01:33:42| peoridcalFire: 0x8457ea8 at 1055136822.107.
2003/06/09 01:33:42| periodicalConnectDone: entry 0x8457ea8 at 1055136822.107
2003/06/09 01:33:42| httpSendRequest: 0x8457ea8 at 1055136822.107.
2003/06/09 01:33:42| eventRun: MaintainSwapSpace at 1055136822.107.
2003/06/09 01:33:42| httpSendComplete: 0x8457ea8 at 1055136822.555.
2003/06/09 01:33:42| eventRun: MaintainSwapSpace at 1055136822.555.
2003/06/09 01:33:42| eventRun: MaintainSwapSpace at 1055136822.555.
2003/06/09 01:33:42| httpReadReply: entry 0x8457ea8 at 1055136822.555
From the trace, we can see a MaintainSwapSpace happened *between
httpSendRequest and httpSendComplete* and this took most of the time.

case 2 (total time is 3000+ms) :
2003/06/09 01:33:26| periodicalConnectDone: entry 0x8464a70 at 1055136806.549
2003/06/09 01:33:26| httpSendRequest: 0x8464a70 at 1055136806.549.
2003/06/09 01:33:26| httpSendComplete: 0x8464a70 at 1055136806.549.
2003/06/09 01:33:26| eventRun: MaintainSwapSpace at 1055136806.552.
2003/06/09 01:33:27| eventRun: MaintainSwapSpace at 1055136807.778.
2003/06/09 01:33:27| eventRun: MaintainSwapSpace at 1055136807.778.
2003/06/09 01:33:28| eventRun: MaintainSwapSpace at 1055136808.779.
2003/06/09 01:33:28| eventRun: MaintainSwapSpace at 1055136808.779.
2003/06/09 01:33:29| eventRun: MaintainSwapSpace at 1055136809.779.
2003/06/09 01:33:29| eventRun: fqdncache_purgelru at 1055136809.779.
2003/06/09 01:33:29| httpReadReply: entry 0x8464a70 at 1055136809.779
From the trace we can see that man MaintainSwapSpace happened *between
httpSendComplete and httpReadReply* and these took most of the time.

But for normal client-squid-httpd model, I never see any eventRun happened
between httpSendRequest-httpSendComplete-httpReadReply in my experiments.
This is very weird because from httpSendRequest on my periodical
contacting http server requests are no different from oridnary http
requests initiated by a client except that the requests in my code have no
client associated. But is that the reason? I can't tell why that could
cause this much delay.

I've been spent a lot of time on this but couldn't find where the problem
is. Hope you gurus can give me some idea. Is eventAdd() is the right way
at all to do this thing I want? Thanks a lot.

--
Chengdu
Received on Mon Jun 09 2003 - 12:58:31 MDT

This archive was generated by hypermail pre-2.1.9 : Tue Dec 09 2003 - 16:20:07 MST