|
|
|
Demo
Discussion
|
|
Forum
Config Examples
Contributions
Vulnerabilities
|
| Discussion forum about ELOG |
Not logged in |
 |
|
|
|
|
|
Message ID: 450
Entry time: Wed Nov 12 12:25:44 2003
Reply to this: 451
|
|
| 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. |
|
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 ...
|