wiki:ProfilingResults

Version 12 (modified by tarmo, 13 years ago) (diff)

Added profiling data

Profiling

Instructions

Turning on profiling in Zope

Edit etc/zope.conf in your Zope folder and uncomment line

#    publisher-profile-file $INSTANCE/var/profile.dat

(search for 'profile' to find this line)

Restart Zope.

Using hammerhead to stress test LeMill

Get the hammerhead configuration from source:/bundle/hammerhead and read source:/bundle/hammerhead/README.txt You'll get nice summary information on the speed of LeMill into the results log file.

Using wget to stress test LeMill

  1. Install wget on your machine (preinstalled on most Linux boxes)
  2. Run wget -r -p -l inf -np http://servername/lemill-server/
    • you can add --delete-after if you don't want to fill your hard drive with the stuff wget downloads.
  3. You won't get any statistics from wget, but this may be useful for profiling.
  4. This may take long time.

Results

Baseline (Jukka)

Let's set the baseline to be Zope's default front page (Zope Quick Start on gray background) and 50 requests with 'ab' command.

Content of lemill is quite-up-to-date lemill.net Data.fs

Jukka (profiling on, Macbook Dualcore 1.8Ghz, 1G mem) :

  • base: 74.70 ms/page
  • empty Plone-site, front page: 2687.90 ms (!)
  • lemill-server/content: 2660.10 ms
  • lemill-server/content/tags: 2936.30 ms
  • lemill-server/activities 2038.20 ms
  • lemill-server/activities/tags: 2133.30 ms
  • lemill-server/tools: 2127.70 ms
  • lemill-server/tools/tags: 2396.60 ms
  • lemill-server/community: 3549.50 ms
  • lemill-server/community/members: 3395.50 ms
  • lemill-server/community/groups: 1879.60 ms

wget traversal of the entire site (Tarmo)

I ran a wget on Zope running on a single core of our development server, running on a lemill.net database from December. In all wget downloaded 79116 files and 1,363,452,832 bytes of data.

The most called methods:

   ncalls            tottime   percall  cumtime   percall filename:lineno(function)
782464131/782450590 -8791.022   -0.000 -8785.652   -0.000 :0(get)
370035833/358418296  5071.200    0.000  3835.203    0.000 :0(getattr)
365691271           -1473.767   -0.000 -1473.767   -0.000 :0(isinstance)
231817795            3996.720    0.000  2345.923    0.000 ZopeGuards.py:52(guarded_getitem)
227457341            1253.080    0.000  1253.080    0.000 :0(append)
199788398/199596269  1148.350    0.000  1152.270    0.000 :0(len)
128742131/128742059   721.810    0.000   723.480    0.000 :0(has_key)
112155574             569.400    0.000   569.400    0.000 :0(cmp)
112155480            2364.540    0.000  4688.523    0.000 Script (Python):149(<lambda.1>)
99351985/99335345    1153.440    0.000  1535.690    0.000 :0(hasattr)
 92580025             616.010    0.000   616.010    0.000 :0(pop)
 75240217             354.800    0.000   354.800    0.000 :0(get_ident)
 65241424            1169.580    0.000 -2235.657   -0.000 FasterStringIO.py:99(write)
 61298194             963.160    0.000  1548.400    0.000 SecurityManagement.py:17(getSecurityManager)
 55727559             315.030    0.000   315.030    0.000 :0(aq_base)
 53928697             313.030    0.000   313.030    0.000 :0(startswith)

Sorted by time (time spent in that method, not including time spent in other methods called by that method). This effectively tells how slowly each method by itself performs. The total amount of time is 35586.580, so for example 3500 in "tottime" would mean 10% of the running time of the server.

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
370035833 5071.200    0.000 3835.203    0.000 :0(getattr)
231817795 3996.720    0.000 2345.923    0.000 ZopeGuards.py:52(guarded_getitem)
112155480 2364.540    0.000 4688.523    0.000 Script (Python):149(<lambda.1>)
  4201451 1951.950    0.000 2781.320    0.001 PlacelessTranslationService.py:556(negotiate_language)
 18813416 1564.340    0.000  287.635    0.000 TALInterpreter.py:282(do_startTag)
227457341 1253.080    0.000 1253.080    0.000 :0(append)
 28292239 1195.310    0.000 3954.810    0.000 :0(guarded_getattr)
 15192348 1175.640    0.000 2137.100    0.000 PythonExpr.py:47(_bind_used_names)
 65241424 1169.580    0.000 -2235.657  -0.000 FasterStringIO.py:99(write)
 99351985 1153.440    0.000 1535.690    0.000 :0(hasattr)
199788398 1148.350    0.000 1152.270    0.000 :0(len)
 41559645 1085.480    0.000 3045.840    0.000 ZopeSecurityPolicy.py:28(getRoles)
 61298194  963.160    0.000 1548.400    0.000 SecurityManagement.py:17(getSecurityManager)
 24379784  875.510    0.000 1460.490    0.000 TALES.py:183(endScope)
 29940016  867.150    0.000 -2796.062  -0.000 Expressions.py:105(_eval)
 41501513  822.490    0.000 21786.154   0.001 TALES.py:215(evaluate)
 28434709  806.010    0.000 7463.046    0.000 Expressions.py:158(_eval)
 26276192  782.820    0.000 1749.540    0.000 Skinnable.py:68(__getattr__)
128742131  721.810    0.000  723.480    0.000 :0(has_key)
 17749167  693.950    0.000  694.020    0.000 :0(aq_get)
  1215949  679.250    0.001 5367.783    0.004 :0(sort)
 14726955  654.480    0.000  654.560    0.000 :0(keys)
 23073496  638.630    0.000 2614.210    0.000 :0(validate)
 92580025  616.010    0.000  616.010    0.000 :0(pop)
112155574  569.400    0.000  569.400    0.000 :0(cmp)
 19657061  524.780    0.000 1404.000    0.000 :0(map)
 14362872  509.350    0.000 1801.780    0.000 TALInterpreter.py:442(do_rawtextBeginScope_tal)
 11045390  420.160    0.000  765.980    0.000 Traversable.py:92(getPhysicalPath)
 15192348  418.740    0.000 13834.481   0.001 ZRPythonExpr.py:42(__call__)
  3988508  418.050    0.000 1730.100    0.000 Traversable.py:109(unrestrictedTraverse)
  9959287  412.810    0.000 30702.860   0.371 TALInterpreter.py:400(no_tag)
 28711469  389.180    0.000 7938.966    0.000 Expressions.py:182(__call__)
 45409104  362.020    0.000  362.020    0.000 :0(copy)
   868597  361.850    0.000 5632.100    0.006 ActionProviderBase.py:79(listActionInfos)
 34873194  361.580    0.000  361.580    0.000 :0(update)
 75240217  354.800    0.000  354.800    0.000 :0(get_ident)
 19031554  346.820    0.000  430.250    0.000 PropertyManager.py:153(getPropertyType)
  7550801  332.710    0.000  505.530    0.000 UserDict.py:40(update)
 24381156  331.740    0.000  654.880    0.000 TALES.py:180(beginScope)
  5511994  331.090    0.000  622.650    0.000 User.py:171(allowed)
 42501600  324.960    0.000  324.960    0.000 :0(join)
22877068   324.580    0.000 2682.900    0.000 ActionInformation.py:84(__getitem__)
 55727559  315.030    0.000  315.030    0.000 :0(aq_base)
  5080409  313.040    0.000 1569.390    0.000 BaseObject.py:1087(__bobo_traverse__)
 53928697  313.030    0.000  313.030    0.000 :0(startswith)
  5511956  300.860    0.000 1918.380    0.000 ImplPython.py:464(checkPermission)

Attachments