MongoDBPlugin Development

using the MongoDBPlugin version comited to svn today, on foswiki 1.1.0, on a dataset of 25,000 dataform using topics, and a query using the ~ operator.

• 192.168.1.130 running mongoDB - ~2seconds
• =192.168.1.103=topic store and query based - ~5.5seconds

both these computers are identical otherwise, 2GRam c2d 1.8, horridly slow disk... running apache 2.2 and using perl CGI only (yes, they both have mongodb installed..).

quad:/home/sven# ab "http://192.168.1.130/f/bin/view/Lauries/TestQuery1"
This is ApacheBench, Version 2.3 <$Revision: 1.18 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 192.168.1.130 (be patient).....done


Server Software:        Apache/2.2.16
Server Hostname:        192.168.1.130
Server Port:            80

Document Path:          /f/bin/view/Lauries/TestQuery1
Document Length:        37370 bytes

Concurrency Level:      1
Time taken for tests:   1.954 seconds
Complete requests:      1
Failed requests:        0
Write errors:           0
Total transferred:      37738 bytes
HTML transferred:       37370 bytes
Requests per second:    0.51 [#/sec] (mean)
Time per request:       1954.077 [ms] (mean)
Time per request:       1954.077 [ms] (mean, across all concurrent requests)
Transfer rate:          18.86 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        6    6   0.0      6       6
Processing:  1949 1949   0.0   1949    1949
Waiting:     1939 1939   0.0   1939    1939
Total:       1954 1954   0.0   1954    1954
quad:/home/sven# ab "http://192.168.1.103/f/bin/view/Lauries/TestQuery1"
This is ApacheBench, Version 2.3 <$Revision: 1.18 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking 192.168.1.103 (be patient).....done


Server Software:        Apache/2.2.16
Server Hostname:        192.168.1.103
Server Port:            80

Document Path:          /f/bin/view/Lauries/TestQuery1
Document Length:        37369 bytes

Concurrency Level:      1
Time taken for tests:   5.409 seconds
Complete requests:      1
Failed requests:        0
Write errors:           0
Total transferred:      37737 bytes
HTML transferred:       37369 bytes
Requests per second:    0.18 [#/sec] (mean)
Time per request:       5409.196 [ms] (mean)
Time per request:       5409.196 [ms] (mean, across all concurrent requests)
Transfer rate:          6.81 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        5    5   0.0      5       5
Processing:  5404 5404   0.0   5404    5404
Waiting:     5393 5393   0.0   5393    5393
Total:       5409 5409   0.0   5409    5409

---

milestone 1

Latest progress - DebugLogPlugin (in svn) adds a http header item telling you how long it took to render the topic request X-Foswiki-Monitor-Debuglogplugin-Rendertime (sans xfer time), and MongoDBPlugin adds a list of times spent querying mongo X-Foswiki-Monitor-Mongodbplugin-Lastquerytime

note that these number differ from the above due to removal of network latencies, and the timer starts after perl compilation.

These number are again for a raw text regex on the raw topic text, which is not a good use of mongodb's capabilitys

sven@quad7:~$ curl -I http://hp4/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Wed, 05 Jan 2011 03:14:44 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: noQuery
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 3.51224 wallclock secs ( 2.96 usr  0.15 sys +  0.10 cusr  0.41 csys =  3.62 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=6c02712d9f41f3a13dbd7572fcae3464; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1

sven@quad7:~$ curl -I http://hp3/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Wed, 05 Jan 2011 02:59:58 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.410422
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 1.58916 wallclock secs ( 0.84 usr +  0.08 sys =  0.92 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=40dabda1b3a4c136e0d0077d67ea77f7; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1

milestone 2

(from 2 client systems at the same time, so perl is hit a bit harder)

sven@hp2:~$ curl -I http://hp3/~sven/core/bin/view/Lauries/TestQuery1
sven@hp1:~$ curl -I http://hp3/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Tue, 08 Feb 2011 04:49:02 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.134943
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 1.64855 wallclock secs ( 0.95 usr +  0.10 sys =  1.05 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=09718e0fc9e873c6488c96ee658e9c5f; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1

or from just one client (more comparible with the previous results)

sven@hp1:~$ curl -I http://hp3/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Tue, 08 Feb 2011 04:50:38 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.131832
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 1.59396 wallclock secs ( 0.92 usr +  0.11 sys =  1.03 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=32d89c2da15b2d9abb30b895481d0620; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-

Milestone 3

day 1

hacked code

sven@hp1:~$ curl -I http://hp3/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Fri, 11 Feb 2011 01:13:23 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.000162
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 1.48638 wallclock secs ( 0.88 usr +  0.09 sys =  0.97 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=62e5b4873a3630905205675be4e0af83; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1

somewhat puzzling - All I did was to use the new trunk listener API to load the data from mongoDB (one at a time, slow and nasty) rather than from .txt file.

much more work is needed, as clearly the roudtrips are silly, and we're still hitting the disk .txt files for topicExists etc, due to legacy arch. but it suggests that its worth doing.

then with slight changes and comited as MongoDBPlugin:67838d0bc7ba

sven@hp1:~$ curl -I http://hp3/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Fri, 11 Feb 2011 04:00:54 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.000163
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 1.48613 wallclock secs ( 0.88 usr +  0.09 sys =  0.97 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=e9a053b93a3aad505b18c4cb0e60018b; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1

-- SvenDowideit - 11 Feb 2011

after another week of fixing bugs in the MetaCache - distro:10c62cc3c781

sven@hp1:~$ time curl -I http://hp3/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Wed, 23 Feb 2011 12:07:05 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.000109
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 1.33302 wallclock secs ( 0.65 usr  0.11 sys +  0.13 cusr  0.03 csys =  0.92 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=66a5b7d7803435aed2a036f5046ddb8a; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1

-- SvenDowideit - 23 Feb 2011

end of milestone 3

hp1 is currently down, as my main server's motherboard is dead

so the tests come from the same HW - with the server's disks in it.

sven@quad:~$ time curl -I http://hp3/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Mon, 28 Mar 2011 07:59:45 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.570112
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 1.30385 wallclock secs ( 0.61 usr +  0.05 sys =  0.66 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=decc6e6d36c3eb32a8ad701ebbbed350; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1


real   0m1.867s
user   0m0.004s
sys   0m0.004s

• end of m2 == 1.59396
• end of m3 == 1.30385

for a gain of just under 300ms.

much greater differences should exist for larger result sets, but we're working on that further for m4.

-- SvenDowideit - 28 Mar 2011

Milestone 4

day 1

changed the schema so that there is one database per web, allowing us a larger number of indexes per web, and possibly allowing mongodb to manage memory more interestingly.

need to totally re-import the webs..

sven@quad7:~$ time curl -I http://hp3/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Tue, 05 Apr 2011 04:13:29 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.162753
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 1.20481 wallclock secs ( 0.58 usr +  0.06 sys =  0.64 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=724e771ebd5dd0460ddc2ee36c153194; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1


real   0m1.761s
user   0m0.000s
sys   0m0.000s

thats another 100ms faster - not at all what I expected.

-- SvenDowideit - 05 Apr 2011

I keep forgetting to do proper comparisons - over the months, I've been making foswiki core changes to fix performance issues that show themselves as bottlenecks in the MongoDBPlugin results, and so foswiki trunk is now faster too - see

sven@quad:~$ ab http://hp4/~sven/core/bin/view/Lauries/TestQuery1
This is ApacheBench, Version 2.3 <$Revision: 1.18 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking hp4 (be patient).....done


Server Software:        Apache/2.2.16
Server Hostname:        hp4
Server Port:            80

Document Path:          /~sven/core/bin/view/Lauries/TestQuery1
Document Length:        38502 bytes

Concurrency Level:      1
Time taken for tests:   3.800 seconds
Complete requests:      1
Failed requests:        0
Write errors:           0
Total transferred:      39006 bytes
HTML transferred:       38502 bytes
Requests per second:    0.26 [#/sec] (mean)
Time per request:       3800.435 [ms] (mean)
Time per request:       3800.435 [ms] (mean, across all concurrent requests)
Transfer rate:          10.02 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:  3800 3800   0.0   3800    3800
Waiting:     3793 3793   0.0   3793    3793
Total:       3800 3800   0.0   3800    3800

and

sven@quad:~$ time curl -I http://hp4/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Mon, 18 Apr 2011 05:11:54 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 3.61898 wallclock secs ( 2.94 usr  0.19 sys +  0.07 cusr  0.54 csys =  3.74 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=4f8c7da44075f8798fcbc59995188c6f; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1


real   0m4.038s
user   0m0.000s
sys   0m0.008s

so foswiki 1.2.0 should be 1.6 seconds faster than 1.1, whereas with MongoDBPlugin, you will get even more speed, and added scalability.

-- SvenDowideit - 18 Apr 2011

mmm, ok, and further comparisons, same query, once as cgi, and then the second using mod_fcgid

sven@quad7:~$ time curl -I http://hp3/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Tue, 19 Apr 2011 04:52:57 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.075974
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 0.810351 wallclock secs ( 0.59 usr +  0.06 sys =  0.65 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=120d695a6eb40773c2a2da893f10e270; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1


real   0m1.365s
user   0m0.000s
sys   0m0.000s
sven@quad7:~$ time curl -I http://hp3/~sven/core/bin/foswiki.fcgi/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Tue, 19 Apr 2011 04:53:05 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/foswiki.fcgi/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.076134, 0.051091
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 18.7475 wallclock secs ( 1.11 usr  0.12 sys +  0.01 cusr  0.00 csys =  1.24 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=8805a10a8b700ff2aca180342bcf7759; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1


real   0m0.717s
user   0m0.000s
sys   0m0.000s

so far, that means we've taken and uncached query over a large web from ~5seconds to 0.7seconds on the same hardware, by offloading the querying to an indexed structured query service, and by avoiding the ~500ms startup cost of CGI

pleasing (m4 continuing, but mostly on non-speed related issues)

-- SvenDowideit - 19 Apr 2011

complete

m4 is almost complete - I've got one more index to add (that should not impact the Glossary queries at all), so here goes with the final-ish numbers:

note that in the last 2 weeks, we've added the _entire topic history into the database, so its now uses about 3 times as much memory as before - on this 32bit test server, it is almost maxing out the 2.5G MongoDb limit, and the server starts to swap.

sven@quad:~$ time curl -I http://hp3/~sven/core/bin/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Wed, 04 May 2011 10:51:44 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.090679
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 0.983436 wallclock secs ( 0.61 usr +  0.05 sys =  0.66 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=e6337d30048658ddf3665ce0f031de77; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1


real   0m1.558s
user   0m0.000s
sys   0m0.008s
sven@quad:~$ time curl -I http://hp3/~sven/core/bin/foswiki.fcgi/view/Lauries/TestQuery1
HTTP/1.1 200 OK
Date: Wed, 04 May 2011 10:51:48 GMT
Server: Apache/2.2.16 (Debian)
X-Foswikiuri: /~sven/core/bin/foswiki.fcgi/view/Lauries/TestQuery1
X-Foswikiaction: view
X-Foswiki-Monitor-Mongodbplugin-Lastquerytime: 0.061654
X-Foswiki-Monitor-Debuglogplugin-Rendertime: 0.792923 wallclock secs ( 0.47 usr +  0.04 sys =  0.51 CPU)
Cache-Control: max-age=0
Set-Cookie: FOSWIKISID=ea8c2eccdd57a203952634bf62ac07fe; path=/; HttpOnly
Vary: Accept-Encoding
Content-Type: text/html; charset=iso-8859-1


real   0m0.890s
user   0m0.008s
sys   0m0.000s

so in the process of adding much more load on the server,its about 200ms slower than without. We might add an option to disable the topic histories, but thats low on our priorities - I have to migrate my test servers to 64bit which will change the results further.

-- SvenDowideit - 04 May 2011