8.68% of my time in assert()?
Recompiled with -O2 -pg. Moved back and forth between two pages (10k and 130k) repeatedly. gprof said: % cumulative self self total time seconds seconds calls ms/call ms/call name 27.43 0.79 0.79 517177 0.00 0.00 dw::Textblock::wordWrap(int) 10.42 1.09 0.30 45 6.67 51.95 Html_write_raw(DilloHtml*, char*, int, int) 8.68 1.34 0.25 5845490 0.00 0.00 lout::misc::assert(bool, char const*, ...) 5.38 1.50 0.16 183777 0.00 0.00 dw::Textblock::addWord(int, int, int, dw::core::style::Style*) 3.47 1.60 0.10 158682 0.00 0.01 dw::Textblock::addText(char const*, dw::core::style::Style*) 2.78 1.68 0.08 151303 0.00 0.00 Html_process_space(DilloHtml*, char const*, int) 2.78 1.76 0.08 143 0.56 0.70 dw::Textblock::sizeAllocateImpl(dw::core::Allocation*) 2.78 1.84 0.08 21 3.81 4.91 dw::Textblock::~Textblock() 2.43 1.91 0.07 145864 0.00 0.00 dw::Textblock::addSpace(dw::core::style::Style*) 2.43 1.98 0.07 38885 0.00 0.00 Html_tag_index(char const*) 2.43 2.05 0.07 utf8towc 1.74 2.10 0.05 517177 0.00 0.00 dw::Textblock::getWordExtremes(dw::Textblock::Word*, dw::core::Extremes*) 1.74 2.15 0.05 158682 0.00 0.00 dw::Textblock::calcTextSize(char const*, dw::core::style::Style*, dw::core::Requisition*) 1.74 2.20 0.05 75140 0.00 0.00 dw::Textblock::addLine(int, bool) 1.74 2.25 0.05 utf8decode 1.74 2.30 0.05 DilloHtml::HtmlLinkReceiver::~HtmlLinkReceiver() 1.56 2.34 0.05 13231 0.00 0.01 Html_get_attr2(DilloHtml*, char const*, int, char const*, int) 1.22 2.38 0.04 13351 0.00 0.00 dw::core::style::StyleAttrs::hashValue() 1.04 2.41 0.03 31375 0.00 0.00 Html_push_tag(DilloHtml*, int) 1.04 2.44 0.03 3861 0.01 0.02 a_Html_set_top_font(DilloHtml*, char const*, int, int, int) 1.04 2.47 0.03 193 0.16 0.23 dw::Textblock::rewrap() 0.69 2.49 0.02 73744 0.00 0.00 dStr_append_c 0.69 2.51 0.02 3020 0.01 0.02 a_Url_new ..(total 2.88 sec.) Naturally I thought that's a lot of time to spend in assert(). I wonder what would happen if I turned off BOUND_CHECKING in SimpleVector in lout/misc.hh. This gave % cumulative self self total time seconds seconds calls ms/call ms/call name 20.75 0.50 0.50 572066 0.00 0.00 dw::Textblock::wordWrap(int) 8.71 0.71 0.21 50 4.20 36.14 Html_write_raw(DilloHtml*, char*, int, int) 6.02 0.86 0.15 83051 0.00 0.00 dw::Textblock::addLine(int, bool) 5.81 1.00 0.14 202074 0.00 0.00 dw::Textblock::addWord(int, int, int, dw::core::style::Style*) 5.60 1.13 0.14 174493 0.00 0.01 dw::Textblock::addText(char const*, dw::core::style::Style*) 5.39 1.26 0.13 157 0.83 0.83 dw::Textblock::sizeAllocateImpl(dw::core::Allocation*) 4.56 1.37 0.11 utf8towc 3.53 1.46 0.09 42701 0.00 0.00 Html_tag_index(char const*) 2.90 1.53 0.07 14483 0.00 0.01 Html_get_attr2(DilloHtml*, char const*, int, char const*, int) 2.90 1.60 0.07 fltk::setfont(fltk::Font*, float) 2.49 1.66 0.06 174493 0.00 0.00 dw::Textblock::calcTextSize(char const*, dw::core::style::Style*, dw::core ::Requisition*) 2.49 1.72 0.06 34442 0.00 0.00 Html_tag_cleanup_at_close(DilloHtml*, int) 2.07 1.77 0.05 174517 0.00 0.00 dw::fltk::FltkPlatform::textWidth(dw::core::style::Font*, char const*, int ) 2.07 1.82 0.05 23 2.17 3.54 dw::Textblock::~Textblock() 2.07 1.87 0.05 fltk::getwidth(char const*, int) 1.66 1.91 0.04 166375 0.00 0.00 Html_process_space(DilloHtml*, char const*, int) 1.66 1.95 0.04 9528 0.00 0.01 Url_object_new 1.24 1.98 0.03 14615 0.00 0.00 dw::core::style::StyleAttrs::hashValue() 1.24 2.01 0.03 7820 0.00 0.00 dw::core::style::StyleAttrs::equals(lout::object::Object*) 1.24 2.04 0.03 212 0.14 0.14 dw::Textblock::rewrap() 0.83 2.06 0.02 160393 0.00 0.00 dw::Textblock::addSpace(dw::core::style::Style*) 0.83 2.08 0.02 11374 0.00 0.00 dw::core::style::drawBackground(dw::core::View*, dw::core::Rectangle*, int , int, int, int, dw::core::style::Style*, bool) 0.83 2.10 0.02 9521 0.00 0.00 a_Url_free .. [snip] .. 0.00 2.41 0.00 44 0.00 0.00 lout::misc::assert(bool, char const*, ...) ..(total 2.41 sec.) I don't know whether -pg affects the ability to inline... and bounds checking is important... but it makes one think that maybe SimpleVector's get() and getRef() might be made cheaper, or we might at least avoid gratuitously making repeated get()s, since it turns out that they are not free. (_and_ I could have run many more trials, but the idea that assert() was even capable of reaching that high was alarming)
On Fri, Sep 05, 2008 at 08:55:17PM +0000, corvid wrote:
Recompiled with -O2 -pg. Moved back and forth between two pages (10k and 130k) repeatedly.
gprof said:
% cumulative self self total time seconds seconds calls ms/call ms/call name 27.43 0.79 0.79 517177 0.00 0.00 dw::Textblock::wordWrap(int) 10.42 1.09 0.30 45 6.67 51.95 Html_write_raw(DilloHtml*, char*, int, int) 8.68 1.34 0.25 5845490 0.00 0.00 lout::misc::assert(bool, char const*, ...) 5.38 1.50 0.16 183777 0.00 0.00 dw::Textblock::addWord(int, int, int, dw::core::style::Style*) 3.47 1.60 0.10 158682 0.00 0.01 dw::Textblock::addText(char const*, dw::core::style::Style*) 2.78 1.68 0.08 151303 0.00 0.00 Html_process_space(DilloHtml*, char const*, int) 2.78 1.76 0.08 143 0.56 0.70 dw::Textblock::sizeAllocateImpl(dw::core::Allocation*) 2.78 1.84 0.08 21 3.81 4.91 dw::Textblock::~Textblock() 2.43 1.91 0.07 145864 0.00 0.00 dw::Textblock::addSpace(dw::core::style::Style*) 2.43 1.98 0.07 38885 0.00 0.00 Html_tag_index(char const*) 2.43 2.05 0.07 utf8towc 1.74 2.10 0.05 517177 0.00 0.00 dw::Textblock::getWordExtremes(dw::Textblock::Word*, dw::core::Extremes*) 1.74 2.15 0.05 158682 0.00 0.00 dw::Textblock::calcTextSize(char const*, dw::core::style::Style*, dw::core::Requisition*) 1.74 2.20 0.05 75140 0.00 0.00 dw::Textblock::addLine(int, bool) 1.74 2.25 0.05 utf8decode 1.74 2.30 0.05 DilloHtml::HtmlLinkReceiver::~HtmlLinkReceiver() 1.56 2.34 0.05 13231 0.00 0.01 Html_get_attr2(DilloHtml*, char const*, int, char const*, int) 1.22 2.38 0.04 13351 0.00 0.00 dw::core::style::StyleAttrs::hashValue() 1.04 2.41 0.03 31375 0.00 0.00 Html_push_tag(DilloHtml*, int) 1.04 2.44 0.03 3861 0.01 0.02 a_Html_set_top_font(DilloHtml*, char const*, int, int, int) 1.04 2.47 0.03 193 0.16 0.23 dw::Textblock::rewrap() 0.69 2.49 0.02 73744 0.00 0.00 dStr_append_c 0.69 2.51 0.02 3020 0.01 0.02 a_Url_new ..(total 2.88 sec.)
Naturally I thought that's a lot of time to spend in assert(). I wonder what would happen if I turned off BOUND_CHECKING in SimpleVector in lout/misc.hh.
This gave
% cumulative self self total time seconds seconds calls ms/call ms/call name 20.75 0.50 0.50 572066 0.00 0.00 dw::Textblock::wordWrap(int) 8.71 0.71 0.21 50 4.20 36.14 Html_write_raw(DilloHtml*, char*, int, int) 6.02 0.86 0.15 83051 0.00 0.00 dw::Textblock::addLine(int, bool) 5.81 1.00 0.14 202074 0.00 0.00 dw::Textblock::addWord(int, int, int, dw::core::style::Style*) 5.60 1.13 0.14 174493 0.00 0.01 dw::Textblock::addText(char const*, dw::core::style::Style*) 5.39 1.26 0.13 157 0.83 0.83 dw::Textblock::sizeAllocateImpl(dw::core::Allocation*) 4.56 1.37 0.11 utf8towc 3.53 1.46 0.09 42701 0.00 0.00 Html_tag_index(char const*) 2.90 1.53 0.07 14483 0.00 0.01 Html_get_attr2(DilloHtml*, char const*, int, char const*, int) 2.90 1.60 0.07 fltk::setfont(fltk::Font*, float) 2.49 1.66 0.06 174493 0.00 0.00 dw::Textblock::calcTextSize(char const*, dw::core::style::Style*, dw::core ::Requisition*) 2.49 1.72 0.06 34442 0.00 0.00 Html_tag_cleanup_at_close(DilloHtml*, int) 2.07 1.77 0.05 174517 0.00 0.00 dw::fltk::FltkPlatform::textWidth(dw::core::style::Font*, char const*, int ) 2.07 1.82 0.05 23 2.17 3.54 dw::Textblock::~Textblock() 2.07 1.87 0.05 fltk::getwidth(char const*, int) 1.66 1.91 0.04 166375 0.00 0.00 Html_process_space(DilloHtml*, char const*, int) 1.66 1.95 0.04 9528 0.00 0.01 Url_object_new 1.24 1.98 0.03 14615 0.00 0.00 dw::core::style::StyleAttrs::hashValue() 1.24 2.01 0.03 7820 0.00 0.00 dw::core::style::StyleAttrs::equals(lout::object::Object*) 1.24 2.04 0.03 212 0.14 0.14 dw::Textblock::rewrap() 0.83 2.06 0.02 160393 0.00 0.00 dw::Textblock::addSpace(dw::core::style::Style*) 0.83 2.08 0.02 11374 0.00 0.00 dw::core::style::drawBackground(dw::core::View*, dw::core::Rectangle*, int , int, int, int, dw::core::style::Style*, bool) 0.83 2.10 0.02 9521 0.00 0.00 a_Url_free .. [snip] .. 0.00 2.41 0.00 44 0.00 0.00 lout::misc::assert(bool, char const*, ...) ..(total 2.41 sec.)
I don't know whether -pg affects the ability to inline... and bounds checking is important... but it makes one think that maybe SimpleVector's get() and getRef() might be made cheaper, or we might at least avoid gratuitously making repeated get()s, since it turns out that they are not free.
(_and_ I could have run many more trials, but the idea that assert() was even capable of reaching that high was alarming)
Yes that's strange. BTW, today I noticed this: After startup with blank page: %MEM VSZ RSS TTY STAT START TIME COMMAND 0.2 56136 4204 pts/8 S+ 19:59 0:00 ./dillo-fltk alarming VSZ when compared when what we had in July: %MEM VSZ RSS TTY STAT START TIME COMMAND 0.2 9676 4156 pts/13 S+ 14:57 0:00 ./dillo-fltk.03Jul -- Cheers Jorge.- PS: The good news at the bottom. I have basic Tabs working here!
Jorge wrote:
BTW, today I noticed this:
After startup with blank page:
%MEM VSZ RSS TTY STAT START TIME COMMAND 0.2 56136 4204 pts/8 S+ 19:59 0:00 ./dillo-fltk
alarming VSZ when compared when what we had in July:
%MEM VSZ RSS TTY STAT START TIME COMMAND 0.2 9676 4156 pts/13 S+ 14:57 0:00 ./dillo-fltk.03Jul
-- Cheers Jorge.-
PS: The good news at the bottom. I have basic Tabs working here!
My VSZ at the moment is 8668. I blame tabs :) Is there something interesting in /proc/$PID/maps?
On Sat, Sep 06, 2008 at 12:21:56AM +0000, corvid wrote:
Jorge wrote:
BTW, today I noticed this:
After startup with blank page:
%MEM VSZ RSS TTY STAT START TIME COMMAND 0.2 56136 4204 pts/8 S+ 19:59 0:00 ./dillo-fltk
alarming VSZ when compared when what we had in July:
%MEM VSZ RSS TTY STAT START TIME COMMAND 0.2 9676 4156 pts/13 S+ 14:57 0:00 ./dillo-fltk.03Jul
-- Cheers Jorge.-
PS: The good news at the bottom. I have basic Tabs working here!
My VSZ at the moment is 8668. I blame tabs :) Is there something interesting in /proc/$PID/maps?
I don't see any change in VSZ either. Cheers, Johannes
On Sat, Sep 06, 2008 at 12:21:56AM +0000, corvid wrote:
Jorge wrote:
BTW, today I noticed this:
After startup with blank page:
%MEM VSZ RSS TTY STAT START TIME COMMAND 0.2 56136 4204 pts/8 S+ 19:59 0:00 ./dillo-fltk
alarming VSZ when compared when what we had in July:
%MEM VSZ RSS TTY STAT START TIME COMMAND 0.2 9676 4156 pts/13 S+ 14:57 0:00 ./dillo-fltk.03Jul
-- Cheers Jorge.-
PS: The good news at the bottom. I have basic Tabs working here!
My VSZ at the moment is 8668. I blame tabs :) Is there something interesting in /proc/$PID/maps?
Nothing that I understand... Fortunately it's not Tabs, the sampled dillo is from 03 July, and today I noticed dillo1 also starts with a similar amount of VSZ. It looks like this system, Ubuntu 64bit, has something weird. I'll chack later, and polish Tabs a bit more. -- Cheers Jorge.-
On Fri, Sep 05, 2008 at 08:03:23PM -0400, Jorge Arellano Cid wrote:
On Fri, Sep 05, 2008 at 08:55:17PM +0000, corvid wrote:
Recompiled with -O2 -pg. Moved back and forth between two pages (10k and 130k) repeatedly.
gprof said:
% cumulative self self total time seconds seconds calls ms/call ms/call name 27.43 0.79 0.79 517177 0.00 0.00 dw::Textblock::wordWrap(int) 10.42 1.09 0.30 45 6.67 51.95 Html_write_raw(DilloHtml*, char*, int, int) 8.68 1.34 0.25 5845490 0.00 0.00 lout::misc::assert(bool, char const*, ...) 5.38 1.50 0.16 183777 0.00 0.00 dw::Textblock::addWord(int, int, int, dw::core::style::Style*) 3.47 1.60 0.10 158682 0.00 0.01 dw::Textblock::addText(char const*, dw::core::style::Style*) 2.78 1.68 0.08 151303 0.00 0.00 Html_process_space(DilloHtml*, char const*, int) 2.78 1.76 0.08 143 0.56 0.70 dw::Textblock::sizeAllocateImpl(dw::core::Allocation*) 2.78 1.84 0.08 21 3.81 4.91 dw::Textblock::~Textblock() 2.43 1.91 0.07 145864 0.00 0.00 dw::Textblock::addSpace(dw::core::style::Style*) 2.43 1.98 0.07 38885 0.00 0.00 Html_tag_index(char const*) 2.43 2.05 0.07 utf8towc 1.74 2.10 0.05 517177 0.00 0.00 dw::Textblock::getWordExtremes(dw::Textblock::Word*, dw::core::Extremes*) 1.74 2.15 0.05 158682 0.00 0.00 dw::Textblock::calcTextSize(char const*, dw::core::style::Style*, dw::core::Requisition*) 1.74 2.20 0.05 75140 0.00 0.00 dw::Textblock::addLine(int, bool) 1.74 2.25 0.05 utf8decode 1.74 2.30 0.05 DilloHtml::HtmlLinkReceiver::~HtmlLinkReceiver() 1.56 2.34 0.05 13231 0.00 0.01 Html_get_attr2(DilloHtml*, char const*, int, char const*, int) 1.22 2.38 0.04 13351 0.00 0.00 dw::core::style::StyleAttrs::hashValue() 1.04 2.41 0.03 31375 0.00 0.00 Html_push_tag(DilloHtml*, int) 1.04 2.44 0.03 3861 0.01 0.02 a_Html_set_top_font(DilloHtml*, char const*, int, int, int) 1.04 2.47 0.03 193 0.16 0.23 dw::Textblock::rewrap() 0.69 2.49 0.02 73744 0.00 0.00 dStr_append_c 0.69 2.51 0.02 3020 0.01 0.02 a_Url_new ..(total 2.88 sec.)
Naturally I thought that's a lot of time to spend in assert(). I wonder what would happen if I turned off BOUND_CHECKING in SimpleVector in lout/misc.hh.
This gave
% cumulative self self total time seconds seconds calls ms/call ms/call name 20.75 0.50 0.50 572066 0.00 0.00 dw::Textblock::wordWrap(int) 8.71 0.71 0.21 50 4.20 36.14 Html_write_raw(DilloHtml*, char*, int, int) 6.02 0.86 0.15 83051 0.00 0.00 dw::Textblock::addLine(int, bool) 5.81 1.00 0.14 202074 0.00 0.00 dw::Textblock::addWord(int, int, int, dw::core::style::Style*) 5.60 1.13 0.14 174493 0.00 0.01 dw::Textblock::addText(char const*, dw::core::style::Style*) 5.39 1.26 0.13 157 0.83 0.83 dw::Textblock::sizeAllocateImpl(dw::core::Allocation*) 4.56 1.37 0.11 utf8towc 3.53 1.46 0.09 42701 0.00 0.00 Html_tag_index(char const*) 2.90 1.53 0.07 14483 0.00 0.01 Html_get_attr2(DilloHtml*, char const*, int, char const*, int) 2.90 1.60 0.07 fltk::setfont(fltk::Font*, float) 2.49 1.66 0.06 174493 0.00 0.00 dw::Textblock::calcTextSize(char const*, dw::core::style::Style*, dw::core ::Requisition*) 2.49 1.72 0.06 34442 0.00 0.00 Html_tag_cleanup_at_close(DilloHtml*, int) 2.07 1.77 0.05 174517 0.00 0.00 dw::fltk::FltkPlatform::textWidth(dw::core::style::Font*, char const*, int ) 2.07 1.82 0.05 23 2.17 3.54 dw::Textblock::~Textblock() 2.07 1.87 0.05 fltk::getwidth(char const*, int) 1.66 1.91 0.04 166375 0.00 0.00 Html_process_space(DilloHtml*, char const*, int) 1.66 1.95 0.04 9528 0.00 0.01 Url_object_new 1.24 1.98 0.03 14615 0.00 0.00 dw::core::style::StyleAttrs::hashValue() 1.24 2.01 0.03 7820 0.00 0.00 dw::core::style::StyleAttrs::equals(lout::object::Object*) 1.24 2.04 0.03 212 0.14 0.14 dw::Textblock::rewrap() 0.83 2.06 0.02 160393 0.00 0.00 dw::Textblock::addSpace(dw::core::style::Style*) 0.83 2.08 0.02 11374 0.00 0.00 dw::core::style::drawBackground(dw::core::View*, dw::core::Rectangle*, int , int, int, int, dw::core::style::Style*, bool) 0.83 2.10 0.02 9521 0.00 0.00 a_Url_free .. [snip] .. 0.00 2.41 0.00 44 0.00 0.00 lout::misc::assert(bool, char const*, ...) ..(total 2.41 sec.)
I don't know whether -pg affects the ability to inline... and bounds checking is important... but it makes one think that maybe SimpleVector's get() and getRef() might be made cheaper, or we might at least avoid gratuitously making repeated get()s, since it turns out that they are not free.
(_and_ I could have run many more trials, but the idea that assert() was even capable of reaching that high was alarming)
Yes that's strange.
We could disable asserts and bounds checking for the release. I'm haven't hit an assert or out of bounds error for quite some time. It's designed to be easily disabled. Cheers, Johannes
participants (3)
-
corvid＠lavabit.com -
jcid＠dillo.org -
Johannes.Hofmann＠gmx.de