RE: Nutch fetcher "waiting" inbetween fetch

[Bogdan Kecman <bo...@alteray.com>]

> > Here we're using one machine for fetching (exclusive at the moment) 
> > with about 50 fetchers and a local Bind-resolver in 
> caching-nameserver setup.
> > Bandwidth of the fetchers is 5 to 10mbit inbound roughly.
> >
> > What I see is that during fetching java is taking 99.9% cpu (all 
> > userland). At the point where the server "stalls" this changes to 
> > 99.9% on system-usage (writing something  to disc?). It stalls for 
> > about 30 seconds or a bit more.
> This sounds suspiciously like a pagedaemon - what's the swap usage?
 
             total       used       free     shared    buffers     cached
Mem:       2074736    1376656     698080          0      31460     866320
-/+ buffers/cache:     478876    1595860
Swap:      1052248          0    1052248

Looks pretty free to me

> Get a thread dump (kill -SIGQUIT) from that java process. 

I have no idea how to interpret this but here it is (running 500 fetcher threads 1 thread per site, 1500 sites)


Full thread dump Java HotSpot(TM) Server VM (1.5.0_07-b03 mixed mode):
"DestroyJavaVM" prio=1 tid=0x6c2467b0 nid=0x2b10 waiting on condition [0x00000000..0xbfffcdb0]

"fetcher499" prio=1 tid=0x6c29d8e0 nid=0x2f23 waiting for monitor entry [0x5bed6000..0x5bed6f30]
        at org.apache.nutch.fetcher.Fetcher$FetcherThread.outputPage(Fetcher.java:277)
        - waiting to lock <0x73054438> (a org.apache.nutch.io.ArrayFile$Writer)
        at org.apache.nutch.fetcher.Fetcher$FetcherThread.handleFetch(Fetcher.java:261)
        at org.apache.nutch.fetcher.Fetcher$FetcherThread.run(Fetcher.java:193)
...
Same for all 500 fetchers
...
"fetcher0" prio=1 tid=0x6c243170 nid=0x2d2e waiting for monitor entry [0x5c2df000..0x5c2df1b0]
        at org.apache.nutch.fetcher.Fetcher$FetcherThread.outputPage(Fetcher.java:277)
        - waiting to lock <0x73054438> (a org.apache.nutch.io.ArrayFile$Writer)
        at org.apache.nutch.fetcher.Fetcher$FetcherThread.handleFetch(Fetcher.java:261)
        at org.apache.nutch.fetcher.Fetcher$FetcherThread.run(Fetcher.java:148)

"MultiThreadedHttpConnectionManager cleanup" daemon prio=1 tid=0x6d4736b8 nid=0x2c94 in Object.wait() [0x60c73000..0x60c73f30]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x72e776a0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x72e776a0> (a java.lang.ref.ReferenceQueue$Lock)
        at org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$ReferenceQueueThread.run(MultiThreadedHttpConnectionManager.java:1082)

"Low Memory Detector" daemon prio=1 tid=0x6e100af0 nid=0x2b20 runnable [0x00000000..0x00000000]
"CompilerThread1" daemon prio=1 tid=0x08120068 nid=0x2b1f waiting on condition [0x00000000..0x6e2822d8]
"CompilerThread0" daemon prio=1 tid=0x0811eff8 nid=0x2b1e waiting on condition [0x00000000..0x6e303358]
"AdapterThread" daemon prio=1 tid=0x0811df20 nid=0x2b1d waiting on condition [0x00000000..0x00000000]
"Signal Dispatcher" daemon prio=1 tid=0x0811d020 nid=0x2b1c waiting on condition [0x00000000..0x00000000]
"Finalizer" daemon prio=1 tid=0x081137a8 nid=0x2b1b in Object.wait() [0x6e686000..0x6e686eb0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x72db4438> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x72db4438> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=1 tid=0x08112100 nid=0x2b1a in Object.wait() [0x6e707000..0x6e707f30]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x72d99e78> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:474)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x72d99e78> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=1 tid=0x0810fc30 nid=0x2b19 runnable
"GC task thread#0 (ParallelGC)" prio=1 tid=0x08076fb0 nid=0x2b15 runnable
"GC task thread#1 (ParallelGC)" prio=1 tid=0x08077c00 nid=0x2b16 runnable
"GC task thread#2 (ParallelGC)" prio=1 tid=0x08078838 nid=0x2b17 runnable
"GC task thread#3 (ParallelGC)" prio=1 tid=0x08079470 nid=0x2b18 runnable
"VM Periodic Task Thread" prio=1 tid=0x6e1020a0 nid=0x2b21 waiting on condition



> When you look at top(1), which of the pid states is the most 
> common? R (runnable) or D (disk-wait)? And check the swap 
> usage, as mentioned above.

top - 20:53:48 up 2 days,  9:57,  1 user,  load average: 3.94, 3.63, 2.82
Tasks:  88 total,   1 running,  87 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.5% us,  0.7% sy,  0.0% ni, 98.8% id,  0.0% wa,  0.0% hi,  0.0% si
Mem:   2074736k total,  1516564k used,   558172k free,    31636k buffers
Swap:  1052248k total,        0k used,  1052248k free,   937644k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
12254 work      16   0 1537m 376m  13m S  123 18.6  10:15.01 java