Demo Discussion
Forum Config Examples Contributions Vulnerabilities
  Discussion forum about ELOG  Not logged in ELOG logo
icon4.gif   speed is very slow if logbook contains many entries, posted by Heiko Scheit on Wed Nov 12 12:25:44 2003 gmon.txt
    icon2.gif   Re: speed is very slow if logbook contains many entries, posted by Stefan Ritt on Wed Nov 12 12:34:02 2003 
       icon2.gif   Re: speed is very slow if logbook contains many entries, posted by Stefan Ritt on Thu Nov 20 17:55:57 2003 
          icon1.gif   Re: speed is very slow if logbook contains many entries, posted by Etienne Van Caillie on Mon Nov 24 10:25:10 2003 
Message ID: 450     Entry time: Wed Nov 12 12:25:44 2003     Reply to this: 451
Icon: Warning  Author: Heiko Scheit  Author Email: h.scheit@mpi-hd.mpg.de 
Category: Bug fix  OS: Linux  ELOG Version: 2.3.9 
Subject: speed is very slow if logbook contains many entries 
This is not really a bug, but elogd was getting really slow with our
logbook.  It took about 4 1/2 seconds just to get the default page in
threaded mode with 15 entries.  The logbook has in total about 2000
entries, though.

After playing around with the compiler option '-gp' and gprof the
problem was found: loc() is called about 18000 times per logbook
access!  (Attached you can find the gprof output.  There might be
other places where to save time: e.g. getcfg().)  The function loc()
calls stat every time to check if the language file was updated and
this takes a long time especially over NFS.

The quick solution for me was to just replace loc() with 'char
*loc(char *orig) {return orig;}'.  Therefore, I cannot use the
localization that I used anymore, which is not a big problem at the
moment.  After that the time to download the default page was only
0.16 s; almost a factor of 30 faster!

I would suggest to only read the language file (AND also the config
file!) once upon startup.  After changing things one has to restart
elogd, which is not so nice, but the long delay is not acceptable.
Another option not to restart elogd is to make elogd respond to a
signal (e.g. kill -HUP) to reread the config and language files.
Attachment 1: gmon.txt  36 kB  | Hide | Hide all
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 37.63      2.19     2.19   452376     0.00     0.00  getcfg
 26.63      3.74     1.55       23     0.07     0.25  show_elog_list
 20.10      4.91     1.17 17561121     0.00     0.00  equal_ustring
  4.30      5.16     0.25  1199948     0.00     0.00  getparam
  3.44      5.36     0.20   895130     0.00     0.00  strlcat
  3.09      5.54     0.18   446914     0.00     0.00  loc
  2.41      5.68     0.14     4075     0.00     0.00  enumcfg
  0.52      5.71     0.03   467670     0.00     0.00  strlcpy
  0.52      5.74     0.03      347     0.00     0.00  enumgrp
  0.52      5.77     0.03                             stat
  0.17      5.78     0.01    76201     0.00     0.00  isparam
  0.17      5.79     0.01      416     0.00     0.00  strsubst
  0.17      5.80     0.01       12     0.00     0.00  rsputs2
  0.17      5.81     0.01        5     0.00     0.00  el_build_index
  0.17      5.82     0.01                             msg_compare_reverse
  0.00      5.82     0.00     8928     0.00     0.00  el_decode
  0.00      5.82     0.00     6192     0.00     0.00  rsprintf
  0.00      5.82     0.00     5290     0.00     0.00  param_in_str
  0.00      5.82     0.00     5290     0.00     0.00  subst_param
  0.00      5.82     0.00     5175     0.00     0.00  build_ref
  0.00      5.82     0.00      536     0.00     0.00  fnmatch1
  0.00      5.82     0.00      447     0.00     0.00  rsputs
  0.00      5.82     0.00      416     0.00     0.00  build_subst_list
  0.00      5.82     0.00      416     0.00     0.00  el_retrieve
  0.00      5.82     0.00      414     0.00     0.00  display_line
  0.00      5.82     0.00      373     0.00     0.00  url_encode
  0.00      5.82     0.00      346     0.00     0.00  strbreak
  0.00      5.82     0.00      254     0.00     0.00  is_user_allowed
  0.00      5.82     0.00      204     0.00     0.00  setparam
  0.00      5.82     0.00      125     0.00     0.00  is_logbook_in_group
  0.00      5.82     0.00      111     0.00     0.00  url_decode
  0.00      5.82     0.00       69     0.00     0.00  display_reply
  0.00      5.82     0.00       46     0.00     0.00  show_page_navigation
  0.00      5.82     0.00       37     0.00     0.16  decode_get
  0.00      5.82     0.00       37     0.00     0.00  initparam
  0.00      5.82     0.00       37     0.00     0.16  interprete
  0.00      5.82     0.00       37     0.00     0.00  scan_attributes
  0.00      5.82     0.00       35     0.00     0.00  check_user_password
  0.00      5.82     0.00       35     0.00     0.00  do_self_register
  0.00      5.82     0.00       35     0.00     0.00  get_user_line
  0.00      5.82     0.00       25     0.00     0.01  get_logbook_hierarchy
  0.00      5.82     0.00       25     0.00     0.00  is_command_allowed
  0.00      5.82     0.00       25     0.00     0.00  show_html_header
  0.00      5.82     0.00       25     0.00     0.00  show_http_header
  0.00      5.82     0.00       25     0.00     0.00  show_standard_header
  0.00      5.82     0.00       25     0.00     0.01  show_standard_title
  0.00      5.82     0.00       23     0.00     0.00  show_page_filters
  0.00      5.82     0.00       12     0.00     0.00  send_file_direct
  0.00      5.82     0.00        5     0.00     0.00  ss_file_find
  0.00      5.82     0.00        2     0.00     0.01  show_elog_message
  0.00      5.82     0.00        1     0.00     0.01  el_index_logbooks
  0.00      5.82     0.00        1     0.00     5.78  server_loop

 %         the percentage of the total running time of the
time       program used by this function.

cumulative a running sum of the number of seconds accounted
 seconds   for by this function and those listed above it.

 self      the number of seconds accounted for by this
seconds    function alone.  This is the major sort for this
           listing.

calls      the number of times this function was invoked, if
           this function is profiled, else blank.
 
 self      the average number of milliseconds spent in this
ms/call    function per call, if this function is profiled,
	   else blank.

 total     the average number of milliseconds spent in this
ms/call    function and its descendents per call, if this 
	   function is profiled, else blank.

name       the name of the function.  This is the minor sort
           for this listing. The index shows the location of
	   the function in the gprof listing. If the index is
	   in parenthesis it shows where it would appear in
	   the gprof listing if it were to be printed.

		     Call graph (explanation follows)


granularity: each sample hit covers 4 byte(s) for 0.17% of 5.82 seconds

index % time    self  children    called     name
                                                 <spontaneous>
[1]     99.3    0.00    5.78                 main [1]
                0.00    5.78       1/1           server_loop [2]
                0.00    0.00       2/452376      getcfg [7]
                0.00    0.00       2/895130      strlcat [10]
-----------------------------------------------
                0.00    5.78       1/1           main [1]
[2]     99.3    0.00    5.78       1         server_loop [2]
                0.00    5.76      37/37          decode_get [3]
                0.00    0.01       1/1           el_index_logbooks [20]
                0.01    0.00      74/347         enumgrp [15]
                0.00    0.00     112/452376      getcfg [7]
                0.00    0.00      60/204         setparam [40]
                0.00    0.00     148/467670      strlcpy [16]
                0.00    0.00     111/17561121     equal_ustring [8]
                0.00    0.00      37/37          initparam [50]
                0.00    0.00      37/111         url_decode [49]
-----------------------------------------------
                0.00    5.76      37/37          server_loop [2]
[3]     99.0    0.00    5.76      37         decode_get [3]
                0.00    5.76      37/37          interprete [4]
                0.00    0.00      74/204         setparam [40]
                0.00    0.00      37/467670      strlcpy [16]
-----------------------------------------------
                0.00    5.76      37/37          decode_get [3]
[4]     99.0    0.00    5.76      37         interprete [4]
                1.55    4.15      23/23          show_elog_list [5]
                0.00    0.02       2/2           show_elog_message [19]
                0.02    0.00     259/347         enumgrp [15]
                0.00    0.01    1093/446914      loc [6]
                0.00    0.01      37/37          scan_attributes [27]
                0.00    0.00     291/452376      getcfg [7]
                0.00    0.00      35/35          do_self_register [32]
                0.00    0.00    1275/76201       isparam [14]
                0.00    0.00      35/35          check_user_password [33]
                0.00    0.00      25/254         is_user_allowed [28]
                0.00    0.00     575/1199948     getparam [9]
                0.00    0.00    1612/17561121     equal_ustring [8]
                0.00    0.00      60/895130      strlcat [10]
                0.00    0.00      86/467670      strlcpy [16]
                0.00    0.00      37/373         url_encode [42]
                0.00    0.00      74/111         url_decode [49]
                0.00    0.00      25/25          is_command_allowed [51]
                0.00    0.00      12/12          send_file_direct [52]
-----------------------------------------------
                1.55    4.15      23/23          interprete [4]
[5]     97.9    1.55    4.15      23         show_elog_list [5]
                0.18    2.90  445096/446914      loc [6]
                0.25    0.55 1187651/1199948     getparam [9]
                0.00    0.13      23/25          show_standard_title [11]
                0.06    0.00  891158/17561121     equal_ustring [8]
                0.01    0.02   74520/76201       isparam [14]
                0.00    0.02     345/414         display_line [18]
                0.00    0.01      46/46          show_page_navigation [25]
                0.00    0.00      69/69          display_reply [29]
                0.00    0.00     207/254         is_user_allowed [28]
                0.00    0.00     621/452376      getcfg [7]
                0.00    0.00      23/23          show_page_filters [31]
                0.00    0.00      23/25          show_standard_header [35]
                0.00    0.00     345/416         el_retrieve [41]
                0.00    0.00     184/373         url_encode [42]
                0.00    0.00      23/346         strbreak [39]
                0.00    0.00      23/895130      strlcat [10]
                0.00    0.00      23/467670      strlcpy [16]
                0.00    0.00     345/6192        rsprintf [45]
                0.00    0.00      23/447         rsputs [48]
-----------------------------------------------
                0.00    0.00      25/446914      show_standard_title [11]
                0.00    0.00      66/446914      show_elog_message [19]
                0.00    0.00     105/446914      do_self_register [32]
                0.00    0.00     138/446914      show_page_navigation [25]
                0.00    0.00     391/446914      show_page_filters [31]
                0.00    0.01    1093/446914      interprete [4]
                0.18    2.90  445096/446914      show_elog_list [5]
[6]     53.1    0.18    2.91  446914         loc [6]
                2.16    0.49  446914/452376      getcfg [7]
                0.20    0.00  893828/895130      strlcat [10]
                0.03    0.00  446914/17561121     equal_ustring [8]
                0.03    0.00  446914/467670      strlcpy [16]
-----------------------------------------------
                                5133             getcfg [7]
                0.00    0.00       1/452376      enumgrp [15]
                0.00    0.00       2/452376      main [1]
                0.00    0.00      10/452376      el_index_logbooks [20]
                0.00    0.00      25/452376      show_http_header [37]
                0.00    0.00      25/452376      show_html_header [34]
                0.00    0.00      35/452376      get_user_line [36]
                0.00    0.00      35/452376      check_user_password [33]
                0.00    0.00      54/452376      show_elog_message [19]
                0.00    0.00      69/452376      show_page_filters [31]
                0.00    0.00     112/452376      server_loop [2]
                0.00    0.00     275/452376      show_standard_title [11]
                0.00    0.00     291/452376      interprete [4]
                0.00    0.00     416/452376      build_subst_list [30]
                0.00    0.00     621/452376      show_elog_list [5]
                0.00    0.00     762/452376      is_user_allowed [28]
                0.01    0.00    1073/452376      scan_attributes [27]
                0.01    0.00    1656/452376      display_line [18]
                2.16    0.49  446914/452376      loc [6]
[7]     46.2    2.19    0.50  452376+5133    getcfg [7]
                0.50    0.00 7453870/17561121     equal_ustring [8]
                                5133             getcfg [7]
-----------------------------------------------
                0.00    0.00      12/17561121     el_index_logbooks [20]
                0.00    0.00      15/17561121     el_build_index [22]
                0.00    0.00      66/17561121     show_elog_message [19]
                0.00    0.00     105/17561121     do_self_register [32]
                0.00    0.00     111/17561121     server_loop [2]
                0.00    0.00     125/17561121     is_logbook_in_group [43]
                0.00    0.00     184/17561121     show_page_filters [31]
                0.00    0.00     254/17561121     is_user_allowed [28]
                0.00    0.00     712/17561121     setparam [40]
                0.00    0.00    1110/17561121     scan_attributes [27]
                0.00    0.00    1612/17561121     interprete [4]
                0.00    0.00    4050/17561121     get_logbook_hierarchy [12]
                0.00    0.00    4175/17561121     enumcfg [13]
                0.00    0.00    5796/17561121     display_line [18]
                0.03    0.00  380655/17561121     isparam [14]
                0.03    0.00  446914/17561121     loc [6]
                0.06    0.00  891158/17561121     show_elog_list [5]
                0.50    0.00 7453870/17561121     getcfg [7]
                0.56    0.00 8370197/17561121     getparam [9]
[8]     20.1    1.17    0.00 17561121         equal_ustring [8]
-----------------------------------------------
                0.00    0.00      28/1199948     show_elog_message [19]
                0.00    0.00      46/1199948     show_page_filters [31]
                0.00    0.00      50/1199948     show_standard_title [11]
                0.00    0.00     575/1199948     interprete [4]
                0.00    0.00    1248/1199948     build_subst_list [30]
                0.00    0.00   10350/1199948     build_ref [26]
                0.25    0.55 1187651/1199948     show_elog_list [5]
[9]     13.9    0.25    0.56 1199948         getparam [9]
                0.56    0.00 8370197/17561121     equal_ustring [8]
-----------------------------------------------
                0.00    0.00       2/895130      show_elog_message [19]
                0.00    0.00       2/895130      main [1]
                0.00    0.00      10/895130      el_index_logbooks [20]
                0.00    0.00      23/895130      show_elog_list [5]
                0.00    0.00      35/895130      get_user_line [36]
                0.00    0.00      60/895130      interprete [4]
                0.00    0.00     294/895130      el_build_index [22]
                0.00    0.00     416/895130      build_subst_list [30]
                0.00    0.00     460/895130      subst_param [38]
                0.20    0.00  893828/895130      loc [6]
[10]     3.4    0.20    0.00  895130         strlcat [10]
-----------------------------------------------
                0.00    0.01       2/25          show_elog_message [19]
                0.00    0.13      23/25          show_elog_list [5]
[11]     2.5    0.00    0.14      25         show_standard_title [11]
                0.00    0.14      25/25          get_logbook_hierarchy [12]
                0.00    0.00     275/452376      getcfg [7]
                0.00    0.00      25/446914      loc [6]
                0.00    0.00      50/1199948     getparam [9]
                0.00    0.00     375/467670      strlcpy [16]
                0.00    0.00     125/125         is_logbook_in_group [43]
                0.00    0.00     125/373         url_encode [42]
                0.00    0.00     975/6192        rsprintf [45]
-----------------------------------------------
                0.00    0.14      25/25          show_standard_title [11]
[12]     2.4    0.00    0.14      25         get_logbook_hierarchy [12]
                0.14    0.00    4075/4075        enumcfg [13]
                0.00    0.00    4050/17561121     equal_ustring [8]
                0.00    0.00    4175/467670      strlcpy [16]
-----------------------------------------------
                0.14    0.00    4075/4075        get_logbook_hierarchy [12]
[13]     2.4    0.14    0.00    4075         enumcfg [13]
                0.00    0.00    4175/17561121     equal_ustring [8]
-----------------------------------------------
                0.00    0.00       2/76201       show_elog_message [19]
                0.00    0.00     105/76201       check_user_password [33]
                0.00    0.00     299/76201       show_page_filters [31]
                0.00    0.00    1275/76201       interprete [4]
                0.01    0.02   74520/76201       show_elog_list [5]
[14]     0.6    0.01    0.03   76201         isparam [14]
                0.03    0.00  380655/17561121     equal_ustring [8]
-----------------------------------------------
                0.00    0.00      14/347         el_index_logbooks [20]
                0.01    0.00      74/347         server_loop [2]
                0.02    0.00     259/347         interprete [4]
[15]     0.5    0.03    0.00     347         enumgrp [15]
                0.00    0.00       1/452376      getcfg [7]
-----------------------------------------------
                0.00    0.00       2/467670      show_elog_message [19]
                0.00    0.00       5/467670      el_index_logbooks [20]
                0.00    0.00      23/467670      show_elog_list [5]
                0.00    0.00      25/467670      show_html_header [34]
                0.00    0.00      37/467670      decode_get [3]
                0.00    0.00      86/467670      interprete [4]
                0.00    0.00     148/467670      server_loop [2]
                0.00    0.00     175/467670      get_user_line [36]
                0.00    0.00     294/467670      el_build_index [22]
                0.00    0.00     371/467670      setparam [40]
                0.00    0.00     373/467670      url_encode [42]
                0.00    0.00     375/467670      show_standard_title [11]
                0.00    0.00     416/467670      el_retrieve [41]
                0.00    0.00    1393/467670      strbreak [39]
                0.00    0.00    2080/467670      build_subst_list [30]
                0.00    0.00    4175/467670      get_logbook_hierarchy [12]
                0.00    0.00   10778/467670      strsubst [21]
                0.03    0.00  446914/467670      loc [6]
[16]     0.5    0.03    0.00  467670         strlcpy [16]
-----------------------------------------------
                                                 <spontaneous>
[17]     0.5    0.03    0.00                 stat [17]
-----------------------------------------------
                0.00    0.00      69/414         display_reply [29]
                0.00    0.02     345/414         show_elog_list [5]
[18]     0.4    0.00    0.02     414         display_line [18]
                0.01    0.00     414/416         strsubst [21]
... 329 more lines ...
ELOG V3.1.5-fe60aaf