Here is the cfstat output from the most recent pause. Note the strange bursts
of template processing within the long pause:
29 39 100 1125-1 -1 0 1 55 0 22 9 30301 113035
26 39 74 1125-1 -1 0 1 55 0 8 1 20766 94099
15 39 43 1125-1 -1 0 0 55 0 12 3 13757 52687
Pg/Sec DB/Sec CP/Sec Reqs Reqs Reqs AvgQ AvgReq AvgDB Bytes Bytes
Now Hi Now Hi Now Hi Q'ed Run'g TO'ed Time Time Time In/Sec Out/Sec
23 39 65 1125-1 -1 0 0 55 0 11 0 20013 54663
14 39 45 1125-1 -1 0 11 55 0 7 123 19695 76612
6 39 35 1125-1 -1 8 15 55 0 23 1 10087 65052
0 39 0 1125-1 -1 35 15 55 0 23 1 17480 0
0 39 0 1125-1 -1 45 15 55 0 23 1 8373 0
0 39 0 1125-1 -1 49 15 55 0 23 1 3667 0
0 39 1 1125-1 -1 50 15 55 0 23 1 861 0
0 39 0 1125-1 -1 52 15 55 0 23 1 1899 0
0 39 0 1125-1 -1 53 15 55 0 23 1 846 0
0 39 0 1125-1 -1 54 15 55 0 23 1 754 0
0 39 0 1125-1 -1 54 15 55 0 23 1 0 0
0 39 1 1125-1 -1 54 15 55 0 23 2505 0 0
0 39 0 1125-1 -1 55 15 55 0 23 2505 847 0
0 39 0 1125-1 -1 55 15 55 0 23 2505 0 0
0 39 0 1125-1 -1 55 15 55 0 23 2505 0 0
0 39 0 1125-1 -1 55 15 55 0 23 2505 0 0
0 39 0 1125-1 -1 56 15 55 0 23 2505 957 0
0 39 0 1125-1 -1 56 15 55 0 23 2505 0 0
0 39 0 1125-1 -1 56 15 55 0 23 2505 0 0
0 39 0 1125-1 -1 57 15 55 0 23 2505 1089 0
0 39 0 1125-1 -1 57 15 55 0 23 2505 0 0
58 58 174 1125-1 -1 42 15 55 440 6018 1 57126 234886
0 58 0 1125-1 -1 52 15 55 440 6018 1 5617 0
Pg/Sec DB/Sec CP/Sec Reqs Reqs Reqs AvgQ AvgReq AvgDB Bytes Bytes
Now Hi Now Hi Now Hi Q'ed Run'g TO'ed Time Time Time In/Sec Out/Sec
0 58 0 1125-1 -1 59 15 55 440 6018 1 4586 0
0 58 0 1125-1 -1 63 15 55 440 6018 1 0 0
0 58 0 1125-1 -1 63 15 55 440 6018 1 0 0
0 58 2 1125-1 -1 64 15 55 440 6018 1 773 0
0 58 0 1125-1 -1 64 15 55 440 6018 1 0 0
0 58 0 1125-1 -1 64 15 55 440 6018 1 0 0
0 58 0 1125-1 -1 66 15 55 440 6018 1 1682 0
0 58 0 1125-1 -1 66 15 55 440 6018 1 0 0
1 58 1 1125-1 -1 66 15 55 5232 16656 2502 738 0
0 58 0 1125-1 -1 66 15 55 5232 16656 2502 0 0
0 58 0 1125-1 -1 66 15 55 5232 16656 2502 0 0
0 58 0 1125-1 -1 66 15 55 5232 16656 2502 0 0
0 58 0 1125-1 -1 66 15 55 5232 16656 2502 0 0
0 58 0 1125-1 -1 66 15 55 5232 16656 2502 0 0
0 58 0 1125-1 -1 66 15 55 5232 16656 2502 0 0
0 58 0 1125-1 -1 66 15 55 5232 16656 2502 0 0
0 58 0 1125-1 -1 66 15 55 5232 16656 2502 0 0
2 58 3 1125-1 -1 65 15 55 16278 23613 313 1094 7211
0 58 0 1125-1 -1 65 15 55 16278 23613 313 0 0
0 58 0 1125-1 -1 65 15 55 16278 23613 313 0 0
0 58 0 1125-1 -1 67 15 55 16278 23613 313 803 0
0 58 0 1125-1 -1 69 15 55 16278 23613 313 0 0
0 58 1 1125-1 -1 73 15 55 16278 23613 12677 0 0
Pg/Sec DB/Sec CP/Sec Reqs Reqs Reqs AvgQ AvgReq AvgDB Bytes Bytes
Now Hi Now Hi Now Hi Q'ed Run'g TO'ed Time Time Time In/Sec Out/Sec
0 58 0 1125-1 -1 73 15 55 16278 23613 12677 0 0
0 58 0 1125-1 -1 73 15 55 16278 23613 12677 0 0
0 58 0 1125-1 -1 73 15 55 16278 23613 12677 0 0
0 58 0 1125-1 -1 73 15 55 16278 23613 12677 0 0
0 58 3 1125-1 -1 73 15 55 16278 23613 24111 0 1918
0 58 0 1125-1 -1 73 15 55 16278 23613 24111 0 0
0 58 0 1125-1 -1 73 15 55 16278 23613 24111 0 0
0 58 0 1125-1 -1 73 15 55 16278 23613 24111 0 0
0 58 1 1125-1 -1 73 15 55 16278 23613 12056 0 0
0 58 0 1125-1 -1 73 15 55 16278 23613 12056 0 0
0 58 0 1125-1 -1 73 15 55 16278 23613 12056 0 0
0 58 0 1125-1 -1 73 15 55 16278 23613 12056 0 0
0 58 0 1125-1 -1 73 15 55 16278 23613 12056 0 0
0 58 3 1125-1 -1 75 15 55 16278 23613 27782 0 1502
0 58 0 1125-1 -1 114 15 55 16278 23613 27782 0 0
0 58 0 1125-1 -1 121 15 55 16278 23613 27782 0 0
0 58 0 1125-1 -1 125 15 55 16278 23613 27782 0 0
0 58 0 1125-1 -1 126 15 55 16278 23613 27782 0 0
0 58 3 1125-1 -1 129 15 55 16278 23613 25996 0 0
0 58 0 1125-1 -1 133 15 55 16278 23613 25996 0 0
0 58 0 1125-1 -1 133 15 55 16278 23613 25996 0 0
0 58 0 1125-1 -1 134 15 55 16278 23613 25996 0 0
0 58 0 1125-1 -1 135 15 55 16278 23613 25996 0 0
Pg/Sec DB/Sec CP/Sec Reqs Reqs Reqs AvgQ AvgReq AvgDB Bytes Bytes
Now Hi Now Hi Now Hi Q'ed Run'g TO'ed Time Time Time In/Sec Out/Sec
95 95 296 1125-1 -1 52 15 55 149 224 9 136012 355324
0 95 1 1125-1 -1 61 15 55 149 224 309 6245 54811
0 95 0 1125-1 -1 71 15 55 149 224 309 2574 0
0 95 0 1125-1 -1 73 15 55 149 224 309 1555 0
0 95 0 1125-1 -1 74 15 55 149 224 309 844 0
129 129 374 1125-1 -1 0 5 55 0 112 1 58000 548691
72 129 178 1125-1 -1 0 1 55 0 94 1 60924 382143
41 129 106 1125-1 -1 0 0 55 0 7 0 32413 214914
41 129 122 1125-1 -1 0 1 55 0 9 1 38338 226501
27 129 72 1125-1 -1 0 0 55 0 24 0 25268 71764
26 129 85 1125-1 -1 0 0 55 0 27 11 24686 156493
22 129 64 1125-1 -1 0 0 55 0 7 1 21354 146196
28 129 95 1125-1 -1 0 1 55 0 14 1 27407 84884
> Jrockit 1.4.2:
>
> java.args=-server -DJINTEGRA_NATIVE_MODE -DJINTEGRA_PREFETCH_ENUMS
> -Xbootclasspath/a:{application.home}/lib/webchartsJava2D.jar
> -Djava.awt.graphicsenv=com.gp.java2d.ExHeadlessGraphicsEnvironment
> -Xmx800m -Xms800m -Xgcprio:pausetime -Xverbosetimestamp
> -Xverboselog:jrockit.txt -Xgcpause
>
> The GC printout below (jrockit.txt) was from the 3 minute period when
> the server was not responding.
>
> What was most unusual is that cfstat did show templates processing for
> a 1 second period once each minute.
>
> So everything would freeze up for 59 seconds, then a burst of
> templates would process for 1-2 seconds, then it would freeze up for
> 59 seconds. It did this 2 or 3 times and then returned to normal.
>
>
> >What type of GC is it running? What are your JVM settings?
> >
> >
> >
> >
> >
> >
> >"This e-mail is from Reed Exhibitions (Gateway House, 28 The Quadrant,
>
> >Richmond, Surrey, TW9 1DN, United Kingdom), a division of Reed
> Business,
> >Registered in England, Number 678540. It contains information which
> is
> >confidential and may also be privileged. It is for the exclusive use
> of the
> >intended recipient(s). If you are not the intended recipient(s)
> please note
> >that any form of distribution, copying or use of this communication
> or the
> >information in it is strictly prohibited and may be unlawful. If you
> have
> >received this communication in error please return it to the sender
> or call
> >our switchboard on +44 (0) 20 89107910. The opinions expressed
> within this
> >communication are not necessarily those expressed by Reed Exhibitions.
> "
> >Visit our website at http://www.reedexpo.com
> >
> >-----Original Message-----
> >From: Terry Ford
> >To: CF-Server
> >Sent: Thu Nov 09 21:11:11 2006
> >Subject: Server pauses... thoughts?
> >
> >We are running CFMX 6.1 on linux RHEL4.
> >
> >Approximately once every 8-12 hours or so our server stops responding
> for
> >about 3 minutes. Symptoms: CF stops processing requests, stops
> queueing,
> >stops timing out requests, stops doing everything.
> >
> >We are using Jrockit 1.4.2 right now, but it also happens under Sun's
> JVM
> >too.
> >
> >cfstat 1:
> >
> >0 11 0 23 -1 -1 127 15 1 137 247 0 0
> 0
> >0 11 0 23 -1 -1 127 15 1 137 247 0 0
> 0
> >0 11 0 23 -1 -1 127 15 1 137 247 0 0
> 0
> >0 11 0 23 -1 -1 127 15 1 137 247 0 0
> 0
> >0 11 0 23 -1 -1 127 15 1 137 247 0 0
> 0
> >... etc.. for 3 minutes.
> >
> >Then it jumps back to life again, taking off as if nothing ever
> happened.
> >
> >I thought perhaps it was a problem with garbage collection, but
> Jrockit's GC
> >debugging looks fine. In fact, it continues to garbage collect
> during that
> >3 minutes, just as it did before the freeze:
> >
> >[gcpause][Thu Nov 9 16:00:07 2006][13912] old collection phase 0-2
> pause
> >time: 7.998000 ms, (start time: 21226.183 s)
> >[gcpause][Thu Nov 9 16:00:07 2006][13912] total mark time: 530.209
> ms
> >[gcpause][Thu Nov 9 16:00:07 2006][13912] total sweep time: 5.027
> ms
> >[gcpause][Thu Nov 9 16:00:07 2006][13912] old collection phase 4-0
> pause
> >time: 27.229000 ms, (start time: 21226.692 s)
> >[gcpause][Thu Nov 9 16:00:07 2006][13912] (pause includes
> compaction: 0.000
> >ms (no compaction), update ref: 0.000 ms)
> >[gcpause][Thu Nov 9 16:01:07 2006][13912] old collection phase 0-2
> pause
> >time: 10.371000 ms, (start time: 21286.774 s)
> >[gcpause][Thu Nov 9 16:01:08 2006][13912] total mark time: 452.252
> ms
> >[gcpause][Thu Nov 9 16:01:08 2006][13912] total sweep time: 39.125
> ms
> >[gcpause][Thu Nov 9 16:01:08 2006][13912] old collection phase 4-0
> pause
> >time: 62.351000 ms, (start time: 21287.204 s)
> >[gcpause][Thu Nov 9 16:01:08 2006][13912] (pause includes
> compaction:
> >30.253 ms (external), update ref: 4.000 ms)
> >[gcpause][Thu Nov 9 16:02:08 2006][13912] old collection phase 0-2
> pause
> >time: 15.459000 ms, (start time: 21347.301 s)
> >[gcpause][Thu Nov 9 16:02:09 2006][13912] total mark time: 581.907
> ms
> >[gcpause][Thu Nov 9 16:02:09 2006][13912] total sweep time: 147.318
> ms
> >[gcpause][Thu Nov 9 16:02:09 2006][13912] old collection phase 4-0
> pause
> >time: 181.771000 ms, (start time: 21347.849 s)
> >[gcpause][Thu Nov 9 16:02:09 2006][13912] (pause includes
> compaction:
> >131.157 ms (internal), update ref: 16.001 ms)
> >[gcpause][Thu Nov 9 16:03:09 2006][13912] old collection phase 0-2
> pause
> >time: 16.870000 ms, (start time: 21408.057 s)
> >
> >So the JVM appears to be fine. The problem is not with the database
> --
> >there are no outstanding queries when this occurs. The network
> connection
> >is fine. The disk is fine. There's a ton of memory. There's no
> paging
> >going on.
> >
> >So... does anyone have any idea what might be causing these
> infrequent yet
> >long pauses?
> >
> >Regards,
>Terry
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~|
Introducing the Fusion Authority Quarterly Update. 80 pages of hard-hitting,
up-to-date ColdFusion information by your peers, delivered to your door four
times a year.
http://www.fusionauthority.com/quarterly
Archive:
http://www.houseoffusion.com/groups/CF-Server/message.cfm/messageid:6163
Subscription: http://www.houseoffusion.com/groups/CF-Server/subscribe.cfm
Unsubscribe:
http://www.houseoffusion.com/cf_lists/unsubscribe.cfm?user=11502.10531.10
