Bugs item #1982101, was opened at 2008-06-02 15:14
Message generated for change (Comment added) made by stmane
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=482468&aid=1982101&group_id=56967
Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: PF/runtime
Group: Pathfinder 0.24
>Status: Closed
>Resolution: Fixed
Priority: 5
Private: No
Submitted By: Wouter Alink (vzzzbx)
>Assigned to: Stefan Manegold (stmane)
Summary: XQ: slowing down
Initial Comment:
MonetDB/XQuery slows down after each query. It seems to be related to the
complexity of the query. If running a simple query (for example "1+1") 10000
times, the first time it executes in .01 second. Then the execution time
gradually increases. The last time it executes in .05 seconds. Only restarting
mserver seems to reduce the execution time again to .01
The following script illustrates the problem:
n=0;
while [ $n -le 10000 ]
do
if [ $(($n % 100)) -eq 0 ]
then
clear
echo "Iteration $n"
time echo '1+1' | mclient -lxq > /dev/null;
fi
echo '1+1' | mclient -lxq > /dev/null;
n=$(($n + 1))
done
Is this expected behavior? (i know that 10000 times executing 1+1 is not really
a good example, but the same behavior is observed with more complex queries)
i'm using: MonetDB-preJune supersourcetarball (28-may-2008), Fedora Core 8,
64bit-oid
----------------------------------------------------------------------
>Comment By: Stefan Manegold (stmane)
Date: 2008-06-05 01:45
Message:
Logged In: YES
user_id=572415
Originator: NO
Fixed in CVS (XQuery_0-24 release branch):
Profiling turned indeed out to be the key to the problem:
I ran Mserver in valgrind and fired 1000 trivial "1+1" XQuery queries,
once using MPS and once using ALG.
kcachegrind revealed that ALG spent *most* of its time in loading and
dropping MIL modules!
A quick look at the code than revealed that in case of ALG, each query was
preceded by
"
module(pathfinder);
module(mkey);
".
Well, this might (have) be(en) handy to run, e.g., `pf -A | Mserver` or
`pf -A | mclient -lmil`, but Mserver is apparently not optimized for just
loading and dropping modules tenth od thousands of times.
Simply removing the above to statements --- assuming that module
pathfinder (and hence module mkey) is loaded when the server is started via
`Mserver --dbinit='module(pathfinder);'` --- makes the 10000 queries
perform equally fast with MPS and ALG without any performance degradation.
I hope that everybody can live with changing `Mserver` into `Mserver
--dbinit='module(pathfinder);'` when using Pathfinder/XQuery.
----------------------------------------------------------------------
Comment By: Stefan Manegold (stmane)
Date: 2008-06-04 23:00
Message:
Logged In: YES
user_id=572415
Originator: NO
forgot to mention:
on my Intel(R) Core(TM)2 Quad CPU Q6600 @ 2.40GHz
with MPS, Mserver starts at ~40% CPU and never exceeds ~45% CPU during the
10000 queries;
with ALG, Mserver starts at ~40% CPU and then continuously grow towards
~90% CPU at the end of the 10000 query sequence.
File Added: StM.fine.log.pdf
----------------------------------------------------------------------
Comment By: Stefan Manegold (stmane)
Date: 2008-06-04 22:57
Message:
Logged In: YES
user_id=572415
Originator: NO
find attached the results of
n=0 ; while [ $n -le 10000 ] ; do printf "%5d " $n ; { time mclient -glx
-s'1+1' >/dev/null ; } 2>&1 | grep real ; n=$(($n + 1)) ; done >
/tmp/MPS.StM.fine.log ; sort -t. -n -k2 /tmp/MPS.StM.fine.log >
/tmp/MPS.StM.fine.log.hist
n=0 ; while [ $n -le 10000 ] ; do printf "%5d " $n ; { time mclient -Glx
-s'1+1' >/dev/null ; } 2>&1 | grep real ; n=$(($n + 1)) ; done >
/tmp/ALG.StM.fine.log ; sort -t. -n -k2 /tmp/ALG.StM.fine.log >
/tmp/ALG.StM.fine.log.hist
tar -cpzf StM.fine.log.tgz *.StM.fine.log*
and
gnuplot> plot "< sed 's|0m||' ALG.StM.fine.log" using 1:3 title 'ALG' with
lines , "< sed 's|0m||' MPS.StM.fine.log" using 1:3 title 'MPS' with lines
... basically, there is a clear tendency with ALG that is not there with
MPS --- why? --- "someone" need to profile "where time goes" ...
File Added: StM.fine.log.tgz
----------------------------------------------------------------------
Comment By: Jan Rittinger (tsheyar)
Date: 2008-06-04 21:25
Message:
Logged In: YES
user_id=993208
Originator: NO
I think the measurements were to coarse. On my maschine (see attached log
ALG.jr.log) there are some few query runs that take really long (see at
4000 -> 4100) whereas most of the other runs seem to evaluate the query in
the same time (first 1000 and last 1000 require each 24 seconds). Note
Mserver was the only active process running with 97% CPU usage all the time
during the test.
One wild guess what could go wrong is that perhaps the query cache gets to
large at some point in time...
File Added: ALG.jr.log
----------------------------------------------------------------------
Comment By: Stefan Manegold (stmane)
Date: 2008-06-04 18:18
Message:
Logged In: YES
user_id=572415
Originator: NO
File Added: MPS.log
----------------------------------------------------------------------
Comment By: Stefan Manegold (stmane)
Date: 2008-06-04 18:17
Message:
Logged In: YES
user_id=572415
Originator: NO
Indeed, the fact that you use the algebra back-end (Mserver --set
xquery_backend=algebra) and not the (still default) milprint_summer
back-end is the crucial info.
With the algebra back-end I can reproduce your slow-down, as the attached
logs show.
In fact, after a slowly degrading sequence of 10000 "1+1" queries via the
algebra back-end, querying the same running server using the
milprint_summer back-end via `mclient -lx -g` is fast (~0.1 sec), again
...
Also, with the algebra back-end, the Mserver seem to grow (leak?) *less*
than with the milprint_summer back-end... !???
Hence, the problem seems to be in the (embedded) algebra compiler, but I
have absolutely no idea what is/causes the problem ...
File Added: ALG.log
----------------------------------------------------------------------
Comment By: Wouter Alink (vzzzbx)
Date: 2008-06-04 15:30
Message:
Logged In: YES
user_id=621590
Originator: YES
i tried it again with the nightly build, and again, the same behavior as i
reported earlier occured.
the execution time seems to gradually increase over time.
the following steps were taken:
-installed using "monetdb-install.sh --enable-xquery"
-deleted the dbfarm and log folders
-started mserver with: Mserver --dbinit="module(pathfinder);" --set
xquery_backend=algebra
p.s. i perhaps forgot to mention that i was testing the algebra version,
the behavior does not occur with the mps frontend.
----------------------------------------------------------------------
Comment By: Lefteris Sidirourgos (lsidir)
Date: 2008-06-04 10:37
Message:
Logged In: YES
user_id=1856546
Originator: NO
This is an interesting observation, but I really cant think from where to
start looking for the problem. Is it true that this delay can be an OS
accumulate overhead? For the more complex queries, do you see an increase
of only few milliseconds (e.g. .04 milliseconds) or this delay is
increasing with the increase of the complexity of the query?
Thank you,
lefteris
----------------------------------------------------------------------
Comment By: Stefan Manegold (stmane)
Date: 2008-06-03 17:18
Message:
Logged In: YES
user_id=572415
Originator: NO
At least with the tiny "1+1" query, I cannot reproduce the problem; time
per query stays at .01 sec:
========
$ n=0 ; while [ $n -le 10000 ] ; do if [ $(($n % 1000)) -eq 0 ] ; then
echo "`date` Iteration $n" ; echo '1+1' | time mclient -lx -t >/dev/null ;
fi ; echo '1+1' | mclient -lx -t >/dev/null ; n=$(($n + 1)) ; done
Tue Jun 3 16:49:16 CEST 2008 Iteration 0
0.00user 0.00system 0:00.01elapsed 26%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (0major+577minor)pagefaults 0swaps
Tue Jun 3 16:49:28 CEST 2008 Iteration 1000
0.00user 0.00system 0:00.01elapsed 27%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (0major+577minor)pagefaults 0swaps
Tue Jun 3 16:49:39 CEST 2008 Iteration 2000
0.00user 0.00system 0:00.01elapsed 36%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (0major+577minor)pagefaults 0swaps
Tue Jun 3 16:49:51 CEST 2008 Iteration 3000
0.00user 0.00system 0:00.01elapsed 30%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (0major+577minor)pagefaults 0swaps
Tue Jun 3 16:50:02 CEST 2008 Iteration 4000
0.00user 0.00system 0:00.01elapsed 20%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (0major+577minor)pagefaults 0swaps
Tue Jun 3 16:50:14 CEST 2008 Iteration 5000
0.00user 0.00system 0:00.01elapsed 36%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (0major+578minor)pagefaults 0swaps
Tue Jun 3 16:50:25 CEST 2008 Iteration 6000
0.00user 0.00system 0:00.01elapsed 30%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (0major+577minor)pagefaults 0swaps
Tue Jun 3 16:50:37 CEST 2008 Iteration 7000
0.00user 0.00system 0:00.01elapsed 10%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (0major+577minor)pagefaults 0swaps
Tue Jun 3 16:50:49 CEST 2008 Iteration 8000
0.00user 0.00system 0:00.01elapsed 20%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (0major+577minor)pagefaults 0swaps
Tue Jun 3 16:51:00 CEST 2008 Iteration 9000
0.00user 0.00system 0:00.01elapsed 20%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (0major+578minor)pagefaults 0swaps
Tue Jun 3 16:51:12 CEST 2008 Iteration 10000
0.00user 0.00system 0:00.01elapsed 30%CPU (0avgtext+0avgdata
0maxresident)k
0inputs+0outputs (0major+577minor)pagefaults 0swaps
========
The above log actually represents the 3rd or 4th 10k query on on the same
Mserver session, i.e., I actually executed 30k-40k queries without any
visible performance degradation...
----------------------------------------------------------------------
You can respond by visiting:
https://sourceforge.net/tracker/?func=detail&atid=482468&aid=1982101&group_id=56967
-------------------------------------------------------------------------
Check out the new SourceForge.net Marketplace.
It's the best place to buy or sell services for
just about anything Open Source.
http://sourceforge.net/services/buy/index.php
_______________________________________________
Monetdb-bugs mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/monetdb-bugs
