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:
otis hvar ~$ 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.java
> :231)
> at
>
org.blojsom.fetcher.StandardFetcher.getEntriesAllCategories(
StandardFetcher.ja
> 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(CachingFetch
> 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
------------------------------------------------------------
-------------
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
|