|
List Info
Thread: Resource contention bug?
|
|
| Resource contention bug? |
|
2006-12-07 04:06:29 |
Ok, strong suggestion to add at least some counts for basic
hits/misses stats to 3.*. Without knowing how useful the
cache is, one can't really tweak it, let alone deal with
situations like mine.
Thanks,
Otis
----- Original Message ----
From: David Czarnecki <david blojsom.com>
To: blojsom-users <blojsom-userslists.sourceforge.net>
Sent: Wednesday, December 6, 2006 10:13:44 PM
Subject: Re: [Blojsom-users] Resource contention bug?
It seems like something is b0rk3d, but no, there's not any
counts maintained
anywhere. Sorry.
On 12/6/06 9:48 PM, "ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
wrote:
> I've got:
> caching-fetcher-refresh=86400
> (1 day, I believe)
>
> Is there any direct way to peek and see what's going on
with the cache?
> For instance, are any hit/miss counts maintained
anywhere?
>
> Otis
>
> ----- Original Message ----
> From: David Czarnecki <davidblojsom.com>
> To: blojsom-users <blojsom-userslists.sourceforge.net>
> Sent: Wednesday, December 6, 2006 8:02:32 PM
> Subject: Re: [Blojsom-users] Resource contention bug?
>
> What is your caching-fetcher-refresh property set to?
>
> On 12/6/06 6:55 PM, "ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
> wrote:
>
>> I increased cache.capacity to 20000 and re-run
Apache benchmark. I saw a
>> super-modest gain - from 0.07 req/sec to 0.12
req/sec.
>> Any ideas? If caching is not working, this is
going to affect me even when I
>> migrate to 3.0.
>> Is there any way to ensure/check that caching is
really in effect?
>>
>> Thanks,
>> Otis
>>
>> ----- Original Message ----
>> From: "ogjunk-blojsomyahoo.com"
<ogjunk-blojsomyahoo.com>
>> To: blojsom-userslists.sourceforge.net
>> Sent: Wednesday, December 6, 2006 4:08:32 PM
>> Subject: Re: [Blojsom-users] Resource contention
bug?
>>
>> Hi,
>>
>> I thought about this little more. 0.07 req/second
is just crazy, so I
>> thought
>> I'd double-check that caching is really enabled
(even though I saw OSCache in
>> JVM thread dumps). Indeed, it IS enabled as
described at
>> http://wiki.blojsom.com/wiki/display/blojsom/Enabli
ng+Caching .
>>
>> There MUST be something wrong there. If caching
really worked, there is no
>> way Blojsom would be this slow. I have
cache.memory=true set in
>> WEB-INF/oscache.properties, so Blojsom should be
serving everything from RAM
>> and really never hitting the disk, yet it
absolutely looks like it is always
>> hitting the disk.
>>
>> It is not like I have a LOT of posts and comments
either, take a look:
>>
>> $ time find blojsom-blogs/otis/ -name *html | wc
-l
>> 218
>>
>> real 0m13.694s
>> user 0m1.482s
>> sys 0m0.748s
>>
>> That's a pretty small number, no? Certainly a lot
smaller than the cache
>> size
>> (1000) I have in oscache.properties.
>>
>> But note how long it took to get all those files?
13-14 seconds. I run this
>> a
>> few times with the same results. That is indeed a
long time, even for a busy
>> server that simpy.com is. But more importantly,
the 13-14 seconds matches
>> the
>> mean time per request number from the Apache
benchmark results below! I
>> think
>> that shows that the cache is not really being used.
>>
>> Poking around some more, I just learned that there
are other types of files
>> there:
>>
>> otishvar ~$ time find
/simpy/blojsom-blogs/otis/ -name *meta | wc -l
>> 6035
>>
>> real 0m20.561s <==== woho!
>> user 0m1.613s
>> sys 0m0.769s
>> otishvar ~$ time find
/simpy/blojsom-blogs/otis/ -name *cmt | wc -l
>> 5905
>>
>> real 0m2.344s
>> user 0m1.567s
>> sys 0m0.739s
>>
>>
>> Now this is leading me somewhere. Circa 6000 *meta
and another 6000 *cmt
>> files. That DOES exceed the cache size! Could
that be the problem?  What
>> exactly gets cached, Dave? Given the above
numbers, what cache.capacity
>> value
>> should I use? 6000+some buffer? 6000+6000+some
buffer?
>>
>> The reason I'm looking further into this is because
even if I migrate to 3.*
>> version, I'll still want things cached, so I do
need to resolve this issue,
>> plus it may be useful for others.
>>
>> Thanks,
>> Otis
>>
>>
>> ----- Original Message ----
>> From: "ogjunk-blojsomyahoo.com"
<ogjunk-blojsomyahoo.com>
>> To: blojsom-userslists.sourceforge.net
>> Sent: Wednesday, December 6, 2006 3:40:16 PM
>> Subject: Re: [Blojsom-users] Resource contention
bug?
>>
>> Hi,
>>
>> Just so you know what kind of performance I'm
seeing, check the output of
>> "ab"
>> (Apache benchmark). Take a look at the
requests/second number - 0.07
>> req/sec!
>> :(
>>
>> Server Software: Apache/1.3.34
>> Server Hostname: blog.simpy.com
>> Server Port: 80
>>
>> Document Path: /
>> Document Length: 87500 bytes
>>
>> Concurrency Level: 1
>> Time taken for tests: 152.436208 seconds
>> Complete requests: 10
>> Failed requests: 0
>> Write errors: 0
>> Total transferred: 878959 bytes
>> HTML transferred: 875000 bytes
>> Requests per second: 0.07 [#/sec] (mean)
>> Time per request: 15243.620 [ms] (mean)
>> Time per request: 15243.620 [ms] (mean,
across all concurrent requests)
>> Transfer rate: 5.63 [Kbytes/sec] received
>>
>> Connection Times (ms)
>> min mean[+/-sd] median max
>> Connect: 89 95 3.4 97 101
>> Processing: 10732 15147 4203.1 14560 26486
>> Waiting: 10171 14540 4205.7 13946 25902
>> Total: 10830 15243 4203.5 14655 26583
>>
>> Percentage of the requests served within a certain
time (ms)
>> 50% 14655
>> 66% 14955
>> 75% 14978
>> 80% 15532
>> 90% 26583
>> 95% 26583
>> 98% 26583
>> 99% 26583
>> 100% 26583 (longest request)
>>
>>
>> ----- Original Message ----
>> From: "ogjunk-blojsomyahoo.com"
<ogjunk-blojsomyahoo.com>
>> To: blojsom-userslists.sourceforge.net
>> Sent: Wednesday, December 6, 2006 3:10:23 PM
>> Subject: Re: [Blojsom-users] Resource contention
bug?
>>
>> Hi,
>>
>> Just for future reference, the latest OSCache
didn't help, and I still see
>> comment loading methods, methods that list the
content of a directory and
>> look
>> at timestamps, etc. I also often see various
Velocity classes, which makes
>> me
>> think they are slowish as well. I'll try moving to
from 2.30 to 3 as soon as
>> I find time. Thanks for your quick answers, Dave!
>>
>> Otis
>>
>> ----- Original Message ----
>> From: David Czarnecki <davidblojsom.com>
>> To: blojsom-users <blojsom-userslists.sourceforge.net>
>> Sent: Monday, December 4, 2006 2:38:20 PM
>> Subject: Re: [Blojsom-users] Resource contention
bug?
>>
>> Aside from trying the new OSCache to see if that
fixes the issue, I wouldn't
>> spend any more time than that.
>>
>>
>> On 12/4/06 2:22 PM, "ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
>> wrote:
>>
>>> Hm, then there might be a bug there.
>>> The servlet container was restarted a few days
ago.
>>> Posts on blog.simpy.com have been requested
many times since the restart.
>>> There have been no new nor updated blog entries
since December 2.
>>>
>>> Yeah, definitely a problem there. I just hit
blog.simpy.com (it takes about
>>> a
>>> minute to load right now), did kill -QUIT
<java pid> and found:
>>>
>>> "Thread-426" daemon prio=1
tid=0x6acc41d0 nid=0x7906 runnable
>>> [0x67dec000..0x67ded1b0]
>>> at
sun.nio.cs.UTF_8$Encoder.encodeArrayLoop(UTF_8.java:460)
>>> at
sun.nio.cs.UTF_8$Encoder.encodeLoop(UTF_8.java:575)
>>> at
java.nio.charset.CharsetEncoder.encode(CharsetEncoder.java:5
44)
>>> at
java.lang.StringCoding$CharsetSE.encode(StringCoding.java:34
2)
>>> at
java.lang.StringCoding.encode(StringCoding.java:378)
>>> at
java.lang.String.getBytes(String.java:812)
>>> at
java.io.UnixFileSystem.getLastModifiedTime(Native Method)
>>> at
java.io.File.lastModified(File.java:795)
>>> at
>>>
org.blojsom.blog.FileBackedBlogComment.load(FileBackedBlogCo
mment.java:94)
>>> at
>>>
>
org.blojsom.blog.FileBackedBlogEntry.loadComment(FileBackedB
logEntry.java:258>>
>
> )
>>> at
>>>
>>
>
org.blojsom.blog.FileBackedBlogEntry.loadComments(FileBacked
BlogEntry.java:232>
>
>>
>> )
>>> at
>>>
org.blojsom.blog.FileBackedBlogEntry.load(FileBackedBlogEntr
y.java:528)
>>> at
>>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesForCategory(St
andardFetcher.jav>>
>
> a
>>> :231)
>>> at
>>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesAllCategories(
StandardFetcher.j>>
>
> a
>>> va:335)
>>>
>>> This looks like comments are being read off of
FS on every request.
>>>
>>> A LOT of threads stuck at the same :414 line:
>>>
>>> "Thread-422" daemon prio=1
tid=0x70773818 nid=0x78f9 waiting for monitor
>>> entry
>>> [0x681f4000..0x681f4fb0]
>>> at
>>>
>
org.blojsom.fetcher.CachingFetcher$AllCategoriesFetcherThrea
d.run(CachingFetc>>
>
> h
>>> er.java:414)
>>> - waiting to lock <0x77797fe0> (a
>>>
com.opensymphony.oscache.general.GeneralCacheAdministrator)
>>> at
java.lang.Thread.run(Thread.java:595)
>>>
>>> ... but as you said, I should try the new
OSCache.
>>> Is it worth (to you and me) to look into this
further now that 3.* runs from
>>> a
>>> DB?
>>>
>>> Thanks,
>>> Otis
>>>
>>> ----- Original Message ----
>>> From: David Czarnecki <davidblojsom.com>
>>> To: blojsom-users <blojsom-userslists.sourceforge.net>
>>> Sent: Monday, December 4, 2006 1:56:36 PM
>>> Subject: Re: [Blojsom-users] Resource
contention bug?
>>>
>>> The loading of all the posts loads the comments
and those are cached
>>> blog-wide.
>>>
>>> Everything might already be in the cache, but
if you've added or update a
>>> blog entry, then the cache needs to refresh.
>>>
>>>
>>> On 12/4/06 1:33 PM, "ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
>>> wrote:
>>>
>>>> Is this a per post cache or a blog-wide
cache? That is, do you load and
>>>> cache
>>>> all comments for all posts at once, or do
you lazy-cache post comments,
>>>> meaning you load and cache them only when
the post is first requested?
>>>>
>>>> I'm asking, because if you do blog-wide
caching or if you cache all
>>>> comments
>>>> for all posts at once, then there is a bug
there, since everything should
>>>> already be cached in my case (servlet
engine was started a few days ago and
>>>> a
>>>> lot of requests have been made against
blog.simpy.com). If you use the
>>>> lazy-loading approach, then seeing tat
thread trace below makes sense.
>>>> Because I see calls that refer to "all
categories" and "all entries", I
>>>> would
>>>> think comments are not cached lazily,
though.
>>>>
>>>> Thanks,
>>>> Otis
>>>>
>>>> ----- Original Message ----
>>>> From: David Czarnecki <davidblojsom.com>
>>>> To: blojsom-users <blojsom-userslists.sourceforge.net>
>>>> Sent: Monday, December 4, 2006 1:25:46 PM
>>>> Subject: Re: [Blojsom-users] Resource
contention bug?
>>>>
>>>> Comments, etc. are cached with the entry.
This is when data is being loaded
>>>> in the cache.
>>>>
>>>> On 12/4/06 12:55 PM,
"ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
>>>> wrote:
>>>>
>>>>>> From that thread dump, it looked
like it might be the way Blojsom is
>>>>>> calling
>>>>>> OSCache that's the problem, but
maybe I misinterpreted the output.
>>>>> I think there are a few other places
where there's room for optimization,
>>>>> although I'm not sure about the
priority of this stuff now that 3.* is
>>>>> based
>>>>> on DB, and not FS any more:
>>>>>
>>>>> "Thread-402" daemon prio=1
tid=0x6fc29eb0 nid=0x731c runnable
>>>>> [0x68afc000..0x68afcf30]
>>>>> at
java.io.UnixFileSystem.getLastModifiedTime(Native Method)
>>>>> at
java.io.File.lastModified(File.java:795)
>>>>> at
org.blojsom.util.BlojsomUtils$1.compare(BlojsomUtils.java:10
24)
>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1307)
>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1296)
>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1296)
>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1296)
>>>>> at
java.util.Arrays.sort(Arrays.java:1223)
>>>>> at
>>>>>
>>>>
>>>
>>
>
org.blojsom.blog.FileBackedBlogEntry.loadComments(FileBacked
BlogEntry.java:226>
>
>>
>>>
>>>>
>>>> )
>>>>> at
>>>>>
org.blojsom.blog.FileBackedBlogEntry.load(FileBackedBlogEntr
y.java:528)
>>>>> at
>>>>>
>>>
>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesForCategory(St
andardFetcher.jav>>
>
>>
>>>
>>> a
>>>>> :231)
>>>>> at
>>>>>
>>>
>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesAllCategories(
StandardFetcher.j>>
>
>>
>>>
>>> a
>>>>> va:335)
>>>>> at
>>>>>
>>>
>>
>
org.blojsom.fetcher.CachingFetcher$AllCategoriesFetcherThrea
d.run(CachingFetc>>
>
>>
>>>
>>> h
>>>>> er.java:415)
>>>>> - locked <0x77797fe0> (a
>>>>>
com.opensymphony.oscache.general.GeneralCacheAdministrator)
>>>>> at
java.lang.Thread.run(Thread.java:595)
>>>>>
>>>>>
>>>>> Those java.io.* calls show we are
hitting the FS, and those two .load*
>>>>> method
>>>>> calls are frequently seen in my thread
dumps. That is likely because
>>>>> blog.simpy.com has a pretty busy FS, so
things get slow in there. I'd
>>>>> imagine
>>>>> you'd want to cache comments, though,
as they typically don't change that
>>>>> frequently, expiring them only when a
new comment gets added, perhaps.
>>>>> Maybe
>>>>> that's already doable, and I just
haven't configured it properly to cache
>>>>> comments, too?
>>>>>
>>>>> Otis
>>>>>
>>>>>
>>>>> ----- Original Message ----
>>>>> From: David Czarnecki <davidblojsom.com>
>>>>> To: blojsom-users <blojsom-userslists.sourceforge.net>
>>>>> Sent: Monday, December 4, 2006 11:33:44
AM
>>>>> Subject: Re: [Blojsom-users] Resource
contention bug?
>>>>>
>>>>> The OSCache references in the lock
waiting make me think it's an issue
>>>>> with
>>>>> OSCache. D'you try using OSCache 2.3.2?
>>>>>
>>>>> <h
ttp://opensymphony.com/oscache/download.action>
>>>>>
>>>>> On 12/4/06 12:20 AM,
"ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
>>>>> wrote:
>>>>>
>>>>>> Hi,
>>>>>>
>>>>>> This may be just something for Dave
to look at, but maybe others would be
>>>>>> interested, too. I run Blojsom
2.30 at http://blog.simpy.com/
under
>>>>>> Jetty.
>>>>>> I've noticed that right after I
restart the servlet container the load
>>>>>> shoots
>>>>>> up, so I decided to see what the
JVM is doing with kill -QUIT . I did
>>>>>> that
>>>>>> on
>>>>>> a few occasions and often saw
Blojsom in states like these:
>>>>>>
>>>>>>
>>>>>> Full thread dump Java HotSpot(TM)
Server VM (1.5.0_08-b03 mixed mode):
>>>>>>
>>>>>> "Thread-410" daemon
prio=1 tid=0x6cbc3cd8 nid=0x4f21 runnable
>>>>>> [0x5e2f6000..0x5e2f6fb0]
>>>>>> at
sun.nio.cs.UTF_8$Encoder.encodeArrayLoop(UTF_8.java:460)
>>>>>> at
sun.nio.cs.UTF_8$Encoder.encodeLoop(UTF_8.java:575)
>>>>>> at
>>>>>>
java.nio.charset.CharsetEncoder.encode(CharsetEncoder.java:5
44)
>>>>>> at
java.lang.StringCoding$CharsetSE.encode(StringCoding.java:34
2)
>>>>>> at
java.lang.StringCoding.encode(StringCoding.java:378)
>>>>>> at
java.lang.String.getBytes(String.java:812)
>>>>>> at
java.io.UnixFileSystem.getLastModifiedTime(Native Method)
>>>>>> at
java.io.File.lastModified(File.java:795)
>>>>>> at
>>>>>>
org.blojsom.util.BlojsomUtils$1.compare(BlojsomUtils.java:10
23)
>>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1307)
>>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1296)
>>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1296)
>>>>>> at
java.util.Arrays.sort(Arrays.java:1223)
>>>>>> at
>>>>>>
>>>>>
>>>>
>>>
>>
>
org.blojsom.blog.FileBackedBlogEntry.loadComments(FileBacked
BlogEntry.java:226>
>
>>
>>>
>>>>
>>>>>
>>>>> )
>>>>>> at
>>>>>>
org.blojsom.blog.FileBackedBlogEntry.load(FileBackedBlogEntr
y.java:528)
>>>>>> at
>>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesForCategory(St
andardFetcher.jav>>
>
>>
>>>
>>>>
>>>> a
>>>>>> :231)
>>>>>> at
>>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesAllCategories(
StandardFetcher.j>>
>
>>
>>>
>>>>
>>>> a
>>>>>> va:335)
>>>>>> at
>>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.CachingFetcher$AllCategoriesFetcherThrea
d.run(CachingFetc>>
>
>>
>>>
>>>>
>>>> h
>>>>>> er.java:415)
>>>>>> - locked <0x74595af0>
(a
>>>>>>
com.opensymphony.oscache.general.GeneralCacheAdministrator)
>>>>>> at
java.lang.Thread.run(Thread.java:595)
>>>>>>
>>>>>> "Thread-409" daemon
prio=1 tid=0x6c55f550 nid=0x4f20 waiting for monitor
>>>>>> entry
>>>>>> [0x5e377000..0x5e377f30]
>>>>>> at
>>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.CachingFetcher$AllCategoriesFetcherThrea
d.run(CachingFetc>>
>
>>
>>>
>>>>
>>>> h
>>>>>> er.java:414)
>>>>>> - waiting to lock
<0x74595af0> (a
>>>>>>
com.opensymphony.oscache.general.GeneralCacheAdministrator)
>>>>>> at
java.lang.Thread.run(Thread.java:595)
>>>>>>
>>>>>> "Thread-408" daemon
prio=1 tid=0x6222bf60 nid=0x4ef0 waiting for monitor
>>>>>> entry
>>>>>> [0x5e3f8000..0x5e3f8eb0]
>>>>>> at
>>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.CachingFetcher$AllCategoriesFetcherThrea
d.run(CachingFetc>>
>
>>
>>>
>>>>
>>>> h
>>>>>> er.java:414)
>>>>>> - waiting to lock
<0x74595af0> (a
>>>>>>
com.opensymphony.oscache.general.GeneralCacheAdministrator)
>>>>>> at
java.lang.Thread.run(Thread.java:595)
>>>>>>
>>>>>> ....
>>>>>>
>>>>>> Note Thread-409|408, Dave. I often
see dozens of these locked at the
>>>>>> exact
>>>>>> same point/line. I haven't looked
at the source, but it feels like some
>>>>>> resource contention issue that you
may want to investigate.
>>>>>>
>>>>>> Otis
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
------------------------------------------------------------
-------------
>>>>>> Take Surveys. Earn Cash. Influence
the Future of IT
>>>>>> Join SourceForge.net's Techsay
panel and you'll get the chance to share
>>>>>> your
>>>>>> opinions on IT & business
topics through brief surveys - and earn cash
>>>>>> http://www.techsay.com/default.
php?page=join.php&p=sourceforge&CID=DEVDEV
>>>>>>
_______________________________________________
>>>>>> Blojsom-users mailing list
>>>>>> Blojsom-userslists.sourceforge.net
>>>>>> https://lists.sourceforge.net/lists/listinfo/blojsom-u
sers
--
David Czarnecki
http://www.blojsom.com/b
log/ | http://blojsom.sf.net
------------------------------------------------------------
-------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the
chance to share your
opinions on IT & business topics through brief surveys -
and earn cash
http://www.techsay.com/default.
php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
Blojsom-users mailing list
Blojsom-userslists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/blojsom-u
sers
------------------------------------------------------------
-------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the
chance to share your
opinions on IT & business topics through brief surveys -
and earn cash
http://www.techsay.com/default.
php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
Blojsom-users mailing list
Blojsom-userslists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/blojsom-u
sers
|
|
| Resource contention bug? |
|
2006-12-07 06:36:16 |
If I did a cached implementation in blojsom 3.x, I'd
probably be looking at
doing something with memcached. It might also be something
to look at
Terracotta ( http://www.terracotta.org/
) now that it's free to add in
clustering now that we're using Spring.
On 12/6/06 11:06 PM, "ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
wrote:
> Ok, strong suggestion to add at least some counts for
basic hits/misses stats
> to 3.*. Without knowing how useful the cache is, one
can't really tweak it,
> let alone deal with situations like mine.
>
> Thanks,
> Otis
>
> ----- Original Message ----
> From: David Czarnecki <davidblojsom.com>
> To: blojsom-users <blojsom-userslists.sourceforge.net>
> Sent: Wednesday, December 6, 2006 10:13:44 PM
> Subject: Re: [Blojsom-users] Resource contention bug?
>
> It seems like something is b0rk3d, but no, there's not
any counts maintained
> anywhere. Sorry.
>
>
> On 12/6/06 9:48 PM, "ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
> wrote:
>
>> I've got:
>> caching-fetcher-refresh=86400
>> (1 day, I believe)
>>
>> Is there any direct way to peek and see what's
going on with the cache?
>> For instance, are any hit/miss counts maintained
anywhere?
>>
>> Otis
>>
>> ----- Original Message ----
>> From: David Czarnecki <davidblojsom.com>
>> To: blojsom-users <blojsom-userslists.sourceforge.net>
>> Sent: Wednesday, December 6, 2006 8:02:32 PM
>> Subject: Re: [Blojsom-users] Resource contention
bug?
>>
>> What is your caching-fetcher-refresh property set
to?
>>
>> On 12/6/06 6:55 PM, "ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
>> wrote:
>>
>>> I increased cache.capacity to 20000 and re-run
Apache benchmark. I saw a
>>> super-modest gain - from 0.07 req/sec to 0.12
req/sec.
>>> Any ideas? If caching is not working, this is
going to affect me even when
>>> I
>>> migrate to 3.0.
>>> Is there any way to ensure/check that caching
is really in effect?
>>>
>>> Thanks,
>>> Otis
>>>
>>> ----- Original Message ----
>>> From: "ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
>>> To: blojsom-userslists.sourceforge.net
>>> Sent: Wednesday, December 6, 2006 4:08:32 PM
>>> Subject: Re: [Blojsom-users] Resource
contention bug?
>>>
>>> Hi,
>>>
>>> I thought about this little more. 0.07
req/second is just crazy, so I
>>> thought
>>> I'd double-check that caching is really enabled
(even though I saw OSCache
>>> in
>>> JVM thread dumps). Indeed, it IS enabled as
described at
>>> http://wiki.blojsom.com/wiki/display/blojsom/Enabli
ng+Caching .
>>>
>>> There MUST be something wrong there. If
caching really worked, there is no
>>> way Blojsom would be this slow. I have
cache.memory=true set in
>>> WEB-INF/oscache.properties, so Blojsom should
be serving everything from RAM
>>> and really never hitting the disk, yet it
absolutely looks like it is always
>>> hitting the disk.
>>>
>>> It is not like I have a LOT of posts and
comments either, take a look:
>>>
>>> $ time find blojsom-blogs/otis/ -name *html |
wc -l
>>> 218
>>>
>>> real 0m13.694s
>>> user 0m1.482s
>>> sys 0m0.748s
>>>
>>> That's a pretty small number, no? Certainly a
lot smaller than the cache
>>> size
>>> (1000) I have in oscache.properties.
>>>
>>> But note how long it took to get all those
files? 13-14 seconds. I run this
>>> a
>>> few times with the same results. That is
indeed a long time, even for a
>>> busy
>>> server that simpy.com is. But more
importantly, the 13-14 seconds matches
>>> the
>>> mean time per request number from the Apache
benchmark results below! I
>>> think
>>> that shows that the cache is not really being
used.
>>>
>>> Poking around some more, I just learned that
there are other types of files
>>> there:
>>>
>>> otishvar ~$ time find
/simpy/blojsom-blogs/otis/ -name *meta | wc -l
>>> 6035
>>>
>>> real 0m20.561s <==== woho!
>>> user 0m1.613s
>>> sys 0m0.769s
>>> otishvar ~$ time find
/simpy/blojsom-blogs/otis/ -name *cmt | wc -l
>>> 5905
>>>
>>> real 0m2.344s
>>> user 0m1.567s
>>> sys 0m0.739s
>>>
>>>
>>> Now this is leading me somewhere. Circa 6000
*meta and another 6000 *cmt
>>> files. That DOES exceed the cache size! Could
that be the problem?
>>> What
>>> exactly gets cached, Dave? Given the above
numbers, what cache.capacity
>>> value
>>> should I use? 6000+some buffer? 6000+6000+some
buffer?
>>>
>>> The reason I'm looking further into this is
because even if I migrate to 3.*
>>> version, I'll still want things cached, so I do
need to resolve this issue,
>>> plus it may be useful for others.
>>>
>>> Thanks,
>>> Otis
>>>
>>>
>>> ----- Original Message ----
>>> From: "ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
>>> To: blojsom-userslists.sourceforge.net
>>> Sent: Wednesday, December 6, 2006 3:40:16 PM
>>> Subject: Re: [Blojsom-users] Resource
contention bug?
>>>
>>> Hi,
>>>
>>> Just so you know what kind of performance I'm
seeing, check the output of
>>> "ab"
>>> (Apache benchmark). Take a look at the
requests/second number - 0.07
>>> req/sec!
>>> :(
>>>
>>> Server Software: Apache/1.3.34
>>> Server Hostname: blog.simpy.com
>>> Server Port: 80
>>>
>>> Document Path: /
>>> Document Length: 87500 bytes
>>>
>>> Concurrency Level: 1
>>> Time taken for tests: 152.436208 seconds
>>> Complete requests: 10
>>> Failed requests: 0
>>> Write errors: 0
>>> Total transferred: 878959 bytes
>>> HTML transferred: 875000 bytes
>>> Requests per second: 0.07 [#/sec] (mean)
>>> Time per request: 15243.620 [ms] (mean)
>>> Time per request: 15243.620 [ms] (mean,
across all concurrent
>>> requests)
>>> Transfer rate: 5.63 [Kbytes/sec]
received
>>>
>>> Connection Times (ms)
>>> min mean[+/-sd] median max
>>> Connect: 89 95 3.4 97 101
>>> Processing: 10732 15147 4203.1 14560 26486
>>> Waiting: 10171 14540 4205.7 13946 25902
>>> Total: 10830 15243 4203.5 14655 26583
>>>
>>> Percentage of the requests served within a
certain time (ms)
>>> 50% 14655
>>> 66% 14955
>>> 75% 14978
>>> 80% 15532
>>> 90% 26583
>>> 95% 26583
>>> 98% 26583
>>> 99% 26583
>>> 100% 26583 (longest request)
>>>
>>>
>>> ----- Original Message ----
>>> From: "ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
>>> To: blojsom-userslists.sourceforge.net
>>> Sent: Wednesday, December 6, 2006 3:10:23 PM
>>> Subject: Re: [Blojsom-users] Resource
contention bug?
>>>
>>> Hi,
>>>
>>> Just for future reference, the latest OSCache
didn't help, and I still see
>>> comment loading methods, methods that list the
content of a directory and
>>> look
>>> at timestamps, etc. I also often see various
Velocity classes, which makes
>>> me
>>> think they are slowish as well. I'll try
moving to from 2.30 to 3 as soon
>>> as
>>> I find time. Thanks for your quick answers,
Dave!
>>>
>>> Otis
>>>
>>> ----- Original Message ----
>>> From: David Czarnecki <davidblojsom.com>
>>> To: blojsom-users <blojsom-userslists.sourceforge.net>
>>> Sent: Monday, December 4, 2006 2:38:20 PM
>>> Subject: Re: [Blojsom-users] Resource
contention bug?
>>>
>>> Aside from trying the new OSCache to see if
that fixes the issue, I wouldn't
>>> spend any more time than that.
>>>
>>>
>>> On 12/4/06 2:22 PM, "ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
>>> wrote:
>>>
>>>> Hm, then there might be a bug there.
>>>> The servlet container was restarted a few
days ago.
>>>> Posts on blog.simpy.com have been requested
many times since the restart.
>>>> There have been no new nor updated blog
entries since December 2.
>>>>
>>>> Yeah, definitely a problem there. I just
hit blog.simpy.com (it takes
>>>> about
>>>> a
>>>> minute to load right now), did kill -QUIT
<java pid> and found:
>>>>
>>>> "Thread-426" daemon prio=1
tid=0x6acc41d0 nid=0x7906 runnable
>>>> [0x67dec000..0x67ded1b0]
>>>> at
sun.nio.cs.UTF_8$Encoder.encodeArrayLoop(UTF_8.java:460)
>>>> at
sun.nio.cs.UTF_8$Encoder.encodeLoop(UTF_8.java:575)
>>>> at
java.nio.charset.CharsetEncoder.encode(CharsetEncoder.java:5
44)
>>>> at
java.lang.StringCoding$CharsetSE.encode(StringCoding.java:34
2)
>>>> at
java.lang.StringCoding.encode(StringCoding.java:378)
>>>> at
java.lang.String.getBytes(String.java:812)
>>>> at
java.io.UnixFileSystem.getLastModifiedTime(Native Method)
>>>> at
java.io.File.lastModified(File.java:795)
>>>> at
>>>>
org.blojsom.blog.FileBackedBlogComment.load(FileBackedBlogCo
mment.java:94)
>>>> at
>>>>
>>
>
org.blojsom.blog.FileBackedBlogEntry.loadComment(FileBackedB
logEntry.java:258>>
>
>>
>> )
>>>> at
>>>>
>>>
>>
>
org.blojsom.blog.FileBackedBlogEntry.loadComments(FileBacked
BlogEntry.java:232>
>
>>
>>>
>>> )
>>>> at
>>>>
org.blojsom.blog.FileBackedBlogEntry.load(FileBackedBlogEntr
y.java:528)
>>>> at
>>>>
>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesForCategory(St
andardFetcher.jav>>
>
>>
>> a
>>>> :231)
>>>> at
>>>>
>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesAllCategories(
StandardFetcher.j>>
>
>>
>> a
>>>> va:335)
>>>>
>>>> This looks like comments are being read off
of FS on every request.
>>>>
>>>> A LOT of threads stuck at the same :414
line:
>>>>
>>>> "Thread-422" daemon prio=1
tid=0x70773818 nid=0x78f9 waiting for monitor
>>>> entry
>>>> [0x681f4000..0x681f4fb0]
>>>> at
>>>>
>>
>
org.blojsom.fetcher.CachingFetcher$AllCategoriesFetcherThrea
d.run(CachingFetc>>
>
>>
>> h
>>>> er.java:414)
>>>> - waiting to lock
<0x77797fe0> (a
>>>>
com.opensymphony.oscache.general.GeneralCacheAdministrator)
>>>> at
java.lang.Thread.run(Thread.java:595)
>>>>
>>>> ... but as you said, I should try the new
OSCache.
>>>> Is it worth (to you and me) to look into
this further now that 3.* runs
>>>> from
>>>> a
>>>> DB?
>>>>
>>>> Thanks,
>>>> Otis
>>>>
>>>> ----- Original Message ----
>>>> From: David Czarnecki <davidblojsom.com>
>>>> To: blojsom-users <blojsom-userslists.sourceforge.net>
>>>> Sent: Monday, December 4, 2006 1:56:36 PM
>>>> Subject: Re: [Blojsom-users] Resource
contention bug?
>>>>
>>>> The loading of all the posts loads the
comments and those are cached
>>>> blog-wide.
>>>>
>>>> Everything might already be in the cache,
but if you've added or update a
>>>> blog entry, then the cache needs to
refresh.
>>>>
>>>>
>>>> On 12/4/06 1:33 PM,
"ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
>>>> wrote:
>>>>
>>>>> Is this a per post cache or a blog-wide
cache? That is, do you load and
>>>>> cache
>>>>> all comments for all posts at once, or
do you lazy-cache post comments,
>>>>> meaning you load and cache them only
when the post is first requested?
>>>>>
>>>>> I'm asking, because if you do blog-wide
caching or if you cache all
>>>>> comments
>>>>> for all posts at once, then there is a
bug there, since everything should
>>>>> already be cached in my case (servlet
engine was started a few days ago
>>>>> and
>>>>> a
>>>>> lot of requests have been made against
blog.simpy.com). If you use the
>>>>> lazy-loading approach, then seeing tat
thread trace below makes sense.
>>>>> Because I see calls that refer to
"all categories" and "all entries", I
>>>>> would
>>>>> think comments are not cached lazily,
though.
>>>>>
>>>>> Thanks,
>>>>> Otis
>>>>>
>>>>> ----- Original Message ----
>>>>> From: David Czarnecki <davidblojsom.com>
>>>>> To: blojsom-users <blojsom-userslists.sourceforge.net>
>>>>> Sent: Monday, December 4, 2006 1:25:46
PM
>>>>> Subject: Re: [Blojsom-users] Resource
contention bug?
>>>>>
>>>>> Comments, etc. are cached with the
entry. This is when data is being
>>>>> loaded
>>>>> in the cache.
>>>>>
>>>>> On 12/4/06 12:55 PM,
"ogjunk-blojsomyahoo.com" <ogjunk-blojsomyahoo.com>
>>>>> wrote:
>>>>>
>>>>>>> From that thread dump, it
looked like it might be the way Blojsom is
>>>>>>> calling
>>>>>>> OSCache that's the problem, but
maybe I misinterpreted the output.
>>>>>> I think there are a few other
places where there's room for optimization,
>>>>>> although I'm not sure about the
priority of this stuff now that 3.* is
>>>>>> based
>>>>>> on DB, and not FS any more:
>>>>>>
>>>>>> "Thread-402" daemon
prio=1 tid=0x6fc29eb0 nid=0x731c runnable
>>>>>> [0x68afc000..0x68afcf30]
>>>>>> at
java.io.UnixFileSystem.getLastModifiedTime(Native Method)
>>>>>> at
java.io.File.lastModified(File.java:795)
>>>>>> at
>>>>>>
org.blojsom.util.BlojsomUtils$1.compare(BlojsomUtils.java:10
24)
>>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1307)
>>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1296)
>>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1296)
>>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1296)
>>>>>> at
java.util.Arrays.sort(Arrays.java:1223)
>>>>>> at
>>>>>>
>>>>>
>>>>
>>>
>>
>
org.blojsom.blog.FileBackedBlogEntry.loadComments(FileBacked
BlogEntry.java:226>
>
>>
>>>
>>>>
>>>>>
>>>>> )
>>>>>> at
>>>>>>
org.blojsom.blog.FileBackedBlogEntry.load(FileBackedBlogEntr
y.java:528)
>>>>>> at
>>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesForCategory(St
andardFetcher.jav>>
>
>>
>>>
>>>>
>>>> a
>>>>>> :231)
>>>>>> at
>>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesAllCategories(
StandardFetcher.j>>
>
>>
>>>
>>>>
>>>> a
>>>>>> va:335)
>>>>>> at
>>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.CachingFetcher$AllCategoriesFetcherThrea
d.run(CachingFetc>>
>
>>
>>>
>>>>
>>>> h
>>>>>> er.java:415)
>>>>>> - locked <0x77797fe0>
(a
>>>>>>
com.opensymphony.oscache.general.GeneralCacheAdministrator)
>>>>>> at
java.lang.Thread.run(Thread.java:595)
>>>>>>
>>>>>>
>>>>>> Those java.io.* calls show we are
hitting the FS, and those two .load*
>>>>>> method
>>>>>> calls are frequently seen in my
thread dumps. That is likely because
>>>>>> blog.simpy.com has a pretty busy
FS, so things get slow in there. I'd
>>>>>> imagine
>>>>>> you'd want to cache comments,
though, as they typically don't change that
>>>>>> frequently, expiring them only when
a new comment gets added, perhaps.
>>>>>> Maybe
>>>>>> that's already doable, and I just
haven't configured it properly to cache
>>>>>> comments, too?
>>>>>>
>>>>>> Otis
>>>>>>
>>>>>>
>>>>>> ----- Original Message ----
>>>>>> From: David Czarnecki <davidblojsom.com>
>>>>>> To: blojsom-users
<blojsom-userslists.sourceforge.net>
>>>>>> Sent: Monday, December 4, 2006
11:33:44 AM
>>>>>> Subject: Re: [Blojsom-users]
Resource contention bug?
>>>>>>
>>>>>> The OSCache references in the lock
waiting make me think it's an issue
>>>>>> with
>>>>>> OSCache. D'you try using OSCache
2.3.2?
>>>>>>
>>>>>> <h
ttp://opensymphony.com/oscache/download.action>
>>>>>>
>>>>>> On 12/4/06 12:20 AM,
"ogjunk-blojsomyahoo.com"
>>>>>> <ogjunk-blojsomyahoo.com>
>>>>>> wrote:
>>>>>>
>>>>>>> Hi,
>>>>>>>
>>>>>>> This may be just something for
Dave to look at, but maybe others would
>>>>>>> be
>>>>>>> interested, too. I run Blojsom
2.30 at http://blog.simpy.com/
under
>>>>>>> Jetty.
>>>>>>> I've noticed that right after I
restart the servlet container the load
>>>>>>> shoots
>>>>>>> up, so I decided to see what
the JVM is doing with kill -QUIT . I did
>>>>>>> that
>>>>>>> on
>>>>>>> a few occasions and often saw
Blojsom in states like these:
>>>>>>>
>>>>>>>
>>>>>>> Full thread dump Java
HotSpot(TM) Server VM (1.5.0_08-b03 mixed mode):
>>>>>>>
>>>>>>> "Thread-410" daemon
prio=1 tid=0x6cbc3cd8 nid=0x4f21 runnable
>>>>>>> [0x5e2f6000..0x5e2f6fb0]
>>>>>>> at
sun.nio.cs.UTF_8$Encoder.encodeArrayLoop(UTF_8.java:460)
>>>>>>> at
sun.nio.cs.UTF_8$Encoder.encodeLoop(UTF_8.java:575)
>>>>>>> at
>>>>>>>
java.nio.charset.CharsetEncoder.encode(CharsetEncoder.java:5
44)
>>>>>>> at
>>>>>>>
java.lang.StringCoding$CharsetSE.encode(StringCoding.java:34
2)
>>>>>>> at
java.lang.StringCoding.encode(StringCoding.java:378)
>>>>>>> at
java.lang.String.getBytes(String.java:812)
>>>>>>> at
java.io.UnixFileSystem.getLastModifiedTime(Native Method)
>>>>>>> at
java.io.File.lastModified(File.java:795)
>>>>>>> at
>>>>>>>
org.blojsom.util.BlojsomUtils$1.compare(BlojsomUtils.java:10
23)
>>>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1307)
>>>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1296)
>>>>>>> at
java.util.Arrays.mergeSort(Arrays.java:1296)
>>>>>>> at
java.util.Arrays.sort(Arrays.java:1223)
>>>>>>> at
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
>
org.blojsom.blog.FileBackedBlogEntry.loadComments(FileBacked
BlogEntry.java:226>
>
>>
>>>
>>>>
>>>>>
>>>>>>
>>>>>> )
>>>>>>> at
>>>>>>>
org.blojsom.blog.FileBackedBlogEntry.load(FileBackedBlogEntr
y.java:528)
>>>>>>> at
>>>>>>>
>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesForCategory(St
andardFetcher.jav>>
>
>>
>>>
>>>>
>>>>>
>>>>> a
>>>>>>> :231)
>>>>>>> at
>>>>>>>
>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.StandardFetcher.getEntriesAllCategories(
StandardFetcher.j>>
>
>>
>>>
>>>>
>>>>>
>>>>> a
>>>>>>> va:335)
>>>>>>> at
>>>>>>>
>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.CachingFetcher$AllCategoriesFetcherThrea
d.run(CachingFetc>>
>
>>
>>>
>>>>
>>>>>
>>>>> h
>>>>>>> er.java:415)
>>>>>>> - locked
<0x74595af0> (a
>>>>>>>
com.opensymphony.oscache.general.GeneralCacheAdministrator)
>>>>>>> at
java.lang.Thread.run(Thread.java:595)
>>>>>>>
>>>>>>> "Thread-409" daemon
prio=1 tid=0x6c55f550 nid=0x4f20 waiting for monitor
>>>>>>> entry
>>>>>>> [0x5e377000..0x5e377f30]
>>>>>>> at
>>>>>>>
>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.CachingFetcher$AllCategoriesFetcherThrea
d.run(CachingFetc>>
>
>>
>>>
>>>>
>>>>>
>>>>> h
>>>>>>> er.java:414)
>>>>>>> - waiting to lock
<0x74595af0> (a
>>>>>>>
com.opensymphony.oscache.general.GeneralCacheAdministrator)
>>>>>>> at
java.lang.Thread.run(Thread.java:595)
>>>>>>>
>>>>>>> "Thread-408" daemon
prio=1 tid=0x6222bf60 nid=0x4ef0 waiting for monitor
>>>>>>> entry
>>>>>>> [0x5e3f8000..0x5e3f8eb0]
>>>>>>> at
>>>>>>>
>>>>>
>>>>
>>>
>>
>
org.blojsom.fetcher.CachingFetcher$AllCategoriesFetcherThrea
d.run(CachingFetc>>
>
>>
>>>
>>>>
>>>>>
>>>>> h
>>>>>>> er.java:414)
>>>>>>> - waiting to lock
<0x74595af0> (a
>>>>>>>
com.opensymphony.oscache.general.GeneralCacheAdministrator)
>>>>>>> at
java.lang.Thread.run(Thread.java:595)
>>>>>>>
>>>>>>> ....
>>>>>>>
>>>>>>> Note Thread-409|408, Dave. I
often see dozens of these locked at the
>>>>>>> exact
>>>>>>> same point/line. I haven't
looked at the source, but it feels like some
>>>>>>> resource contention issue that
you may want to investigate.
>>>>>>>
>>>>>>> Otis
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
------------------------------------------------------------
------------>>>>>>>
-
>>>>>>> Take Surveys. Earn Cash.
Influence the Future of IT
>>>>>>> Join SourceForge.net's Techsay
panel and you'll get the chance to share
>>>>>>> your
>>>>>>> opinions on IT & business
topics through brief surveys - and earn cash
>>>>>>>
http
://www.techsay.com/default.php?page=join.php&p=sourcefor
ge&CID=DEVDE>>>>>>>
V
>>>>>>>
_______________________________________________
>>>>>>> Blojsom-users mailing list
>>>>>>> Blojsom-userslists.sourceforge.net
>>>>>>> https://lists.sourceforge.net/lists/listinfo/blojsom-u
sers
--
David Czarnecki
http://www.blojsom.com/b
log/ | http://blojsom.sf.net
------------------------------------------------------------
-------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the
chance to share your
opinions on IT & business topics through brief surveys -
and earn cash
http://www.techsay.com/default.
php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
Blojsom-users mailing list
Blojsom-userslists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/blojsom-u
sers
|
|
[1-2]
|
|