Slow to compile keymaps on armel

Bug #338729 reported by Loïc Minier
4
Affects Status Importance Assigned to Milestone
console-setup (Ubuntu)
Invalid
Low
Unassigned

Bug Description

Hi,

It takes 25 s to run "ckbcomp -model pc105 us >/dev/null" on a TI EVM board running jaunty/armel; this board is 500 MHz. On a 800 MHz Freescale Babbage board running jaunty/armel but perhaps building a different keymap, it's in the 5 seconds, and on my amd64 desktop it's sub-second.

ckbcomp could benefit from benchmarks and optimizations. We tried to add "use integer;" at the top and it didn't help.

Notes from conversation with Colin below; anybody is welcome to pickup the research.
12:22 < lool> cjwatson: Will it affect first boot?
12:22 < cjwatson> no, it won't
12:23 < cjwatson> it's interesting that it's so slow though
12:23 < lool> cjwatson: Ok, so it's normal that it takes so long on
              console-setup upgrades?
12:23 < lool> Right, I find that really slow
12:23 < cjwatson> ckbcomp only uses maybe 5MB of memory tops
12:23 < cjwatson> $ time ckbcomp -model pc105 us '' '' >/dev/null
12:23 < cjwatson> real 0m0.618s
12:24 < lool> time (ckbcomp -model pc105 us >/dev/null) => 0m26.826s
12:24 < cjwatson> lool: is it possible that 'use integer;' near the top of
                  ckbcomp would speed it up?
12:24 < lool> I don't see any faults in /proc/cpu/alignment
12:25 < cjwatson> I don't think it needs FP math
12:25 < lool> That's likely, trying
12:25 < lool> 0m25.583s
12:25 < lool> no
12:26 < cjwatson> might be worth trying it with -v 10 and seeing what's taking
                  time
12:27 < cjwatson> oh, hmm, -v 10 actually not that informative
12:27 -!- ember [n=pmf@ubuntu/member/ember] has quit [Read error: 104
          (Connection reset by peer)]
12:28 < cjwatson> verbose perl debugging will probably slow the whole thing
                  down to the point of making it hard to tell
12:28 < cjwatson> maybe just print debugging at appropriate points?
12:29 < lool> Ok
12:33 < cjwatson> I don't have any other obvious bright ideas :-(
12:36 < lool> cjwatson: time is spent on iterations of this loop foreach my
              $key (sort {$a <=> $b} (keys %symbols_table)) {
12:44 < cjwatson> lool: would be useful to know how many elements
                  %symbols_table has, and the same recursively for its elements
12:44 < cjwatson> the actual work done in the inner loop is trivial
12:45 < cjwatson> if the hash lookups are taking ages then we could arrange to
                  do that just once
12:46 < lool> cjwatson: flatten() is the one taking most time
12:47 < cjwatson> lool: flatten() isn't in the loop you mentioned ...
12:48 < cjwatson> oh, you're talking about a different loop than I'm looking at
12:48 * cjwatson starts again
12:50 < cjwatson> lool: the Devel::DProf module might help here
12:51 < cjwatson> 'perl -d:DProf /usr/bin/ckbcomp -model pc105 us >/dev/null'
                  will produce tmon.out and dprofpp can analyse that
...
12:48 < cjwatson> oh, you're talking about a different loop than I'm looking at
12:48 * cjwatson starts again
12:50 < cjwatson> lool: the Devel::DProf module might help here
12:51 < cjwatson> 'perl -d:DProf /usr/bin/ckbcomp -model pc105 us >/dev/null'
                  will produce tmon.out and dprofpp can analyse that
12:52 < persia> pitti, When you get a chance, could you look at bug #309396?
                There's some interest in getting it into -proposed before the
                Alpha Freeze.

Bye

Tags: armel
Revision history for this message
Loïc Minier (lool) wrote :

dprofpp -u
Total Elapsed Time = 27.45491 Seconds
         User Time = 24.52491 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
 51.7 12.70 12.701 106928 0.0001 0.0001 main::approximate
 40.0 9.831 26.264 103 0.0954 0.2550 main::flatten
 16.4 4.030 4.030 9 0.4477 0.4477 main::file_to_string
 9.94 2.437 2.437 26368 0.0001 0.0001 main::distance
 1.83 0.448 1.021 1648 0.0003 0.0006 main::x_to_kernelsym
 1.63 0.400 0.400 2 0.2000 0.2000 utf8::SWASHNEW
 1.12 0.274 0.274 1648 0.0002 0.0002 main::x_to_ascii
 1.10 0.271 0.611 3 0.0904 0.2037 main::xkb_keycodes_definitions
 0.95 0.233 0.282 132 0.0018 0.0021 main::xkb_key
 0.78 0.192 0.192 1048 0.0002 0.0002 main::matches_pattern
 0.57 0.140 0.140 3 0.0466 0.0465 main::BEGIN
 0.38 0.094 0.094 784 0.0001 0.0001 main::uni_to_legacy
 0.22 0.055 0.055 105 0.0005 0.0005 main::print_vector
 0.17 0.041 1.344 6 0.0069 0.2241 main::xkb_symbols_definitions
 0.16 0.040 0.040 445 0.0001 0.0001 main::xkb_method

Paul Larson (pwlars)
tags: added: armel
Revision history for this message
Paul Larson (pwlars) wrote :

confirmed on karmic final:
on my laptop (amd64):
$ time ckbcomp -model pc105 us > /dev/null
real 0m1.059s
user 0m0.820s
sys 0m0.020s

imx51:
$ time ckbcomp -model pc105 us> /dev/null
real 0m17.489s
user 0m7.770s
sys 0m0.030s

Changed in console-setup (Ubuntu):
importance: Undecided → Low
status: New → Triaged
Revision history for this message
Mörgæs (moergaes) wrote :

Closing due to age.
If a similar bug appears in 15.04 (development) please open a new report.

Changed in console-setup (Ubuntu):
status: Triaged → Invalid
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Bug attachments

Remote bug watches

Bug watches keep track of this bug in other bug trackers.