Last Comment Bug 814942 - Excessive I/O read bytes with addon location bar enhancer
: Excessive I/O read bytes with addon location bar enhancer
Status: RESOLVED FIXED
:
Product: Tech Evangelism
Classification: Other
Component: Add-ons (show other bugs)
: unspecified
: x86_64 Windows 7
: -- normal (vote)
: ---
Assigned To: Nobody; OK to take it and work on it
:
:
Mentors:
http://screenr.com/swS7
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2012-11-25 01:23 PST by mayankleoboy1
Modified: 2012-12-01 07:00 PST (History)
6 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---


Attachments
stats after 30mins of browsing. (79.19 KB, image/png)
2012-11-25 23:03 PST, mayankleoboy1
no flags Details
Task manager screenshot (25.26 KB, image/png)
2012-11-29 22:08 PST, Girish Sharma [:Optimizer]
no flags Details

Description mayankleoboy1 2012-11-25 01:23:54 PST
User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:20.0) Gecko/20.0 Firefox/20.0
Build ID: 20121124130632

Steps to reproduce:

1. Install this addon :  https://addons.mozilla.org/en-us/firefox/addon/ui-enhancer/

2. Go to :  http://aordisco.blogspot.in/
3. Click on the first image. A  manual slideshow thingy will start.
4. Open task manager.  View the column : "I/O read bytes"

5. For each image in the slideshow, the I/O read increases by 133MB.  If you view 20-30 images, the I/O read bytes reaches 10GB!


Actual results:

Increase i/o


Expected results:

Less i/o

I can reproduce this with disabling all addons, and enabling only location bar enhancer. 
Vice versa, if all addons- except this- are enabled, increase io does not occur.

But i am unable to reproduce this in a new profile.
Comment 2 mayankleoboy1 2012-11-25 23:03:00 PST
Created attachment 685050 [details]
stats after 30mins of browsing.

Stats after 30 mins of web browsing.
Comment 3 mayankleoboy1 2012-11-29 04:00:58 PST
Also, by doing certain actions, its possible to continuosly infinitely increase the "I/O read bytes" 

The URL is a screen record of it. In the task manager you can see that the "I/O read bytes" counter is continously increasing. It reaches 24GB in ~ 15 seconds.
Comment 4 André Ziegler 2012-11-29 07:27:19 PST
install the nightly version (which supports profiling) and run xperf while you have the high HDD usage:

http://blogs.msdn.com/b/ntdebugging/archive/2009/08/17/xperf-to-investigate-slow-i-o-issues.aspx

zip the etl file and upload it.
Comment 5 mayankleoboy1 2012-11-29 07:43:19 PST
getting "xperf is not recognised as an internal command". Also, i dont know how to point the bat to the file. Can you edit the script so that it saves the etl in "c:" ?


Also, i am using a SSD. And during the time when the I/O read bytes are increasing, there is no significant Disc activity. So the script might not work or something.
Comment 6 mayankleoboy1 2012-11-29 07:59:40 PST
OK, i just copied the profile to a different computer with a HDD and win8. 
When i repro the STR of comment #3, the "i/o read bytes" continously grows. But the HDD is *NOT* being accessed. There is no HDD LED glowing, no slowing associated with high HDD access.  Only the value in the task manager keeps on growing continuously.
Comment 8 Nicholas Nethercote [:njn] 2012-11-29 14:47:05 PST
"I/O Read Bytes" means "The number of read input/output operations generated by the process, including file, network, and device I/Os", according to http://windows.microsoft.com/en-US/windows-vista/What-do-the-Task-Manager-memory-columns-mean.
Comment 9 Kris Maglione [:kmag] 2012-11-29 15:14:49 PST
CCing developer.
Comment 10 Girish Sharma [:Optimizer] 2012-11-29 21:47:46 PST
First of all, let me ask, is this a bad thing ?
I was unaware of that column so did not see the behavior myself before.

For each url change, my add-on does a query to places db to know if there exists pages of same url (something like that), which might increase the I/O per url change. But I will have to look further why the increase is so much.

I have one final question : Is this issue causing performance degradation ? or memory hog, or any similar problem ?
Comment 11 André Ziegler 2012-11-29 21:51:32 PST
again, make the xperf trace while you think you have this issue.
Comment 12 Girish Sharma [:Optimizer] 2012-11-29 21:56:05 PST
FWIW, the cleopatra profile does not help as the CPU usage of my add-on is minimal. Moreover, the major cpu usage by my add-on is used up in determining the urlbar width, and other non IO related stuff.

I will check out sperf and see what results I get.
Comment 13 mayankleoboy1 2012-11-29 22:00:34 PST
>First of all, let me ask, is this a bad thing ?

I dont know. But IMHO, a continuous unbound increase in a value would be a metter of concern.

>I have one final question : Is this issue causing performance degradation ? or >memory hog, or any similar problem ?

No for both.

In comment #3, the CPU usage gets 100%. And closing Nightly does not end the process. You have to "end task" it.
Comment 14 Nicholas Nethercote [:njn] 2012-11-29 22:05:00 PST
> >First of all, let me ask, is this a bad thing ?
> 
> I dont know. But IMHO, a continuous unbound increase in a value would be a
> metter of concern.

I'm skeptical.  Trust your eyes or a stopwatch, not some weird measurement nobody's heard of...
Comment 15 mayankleoboy1 2012-11-29 22:07:46 PST
please note that STR in comment #0 are a specific case.   Even in normal browsing, the value quickly reaches large value. In about 30mins of browsing, i see the value as 17GB. But the value does not keep on increasing by itself.

STR in comment #3 are another case. Here the value automatically keeps on increasing. I left the browser for ~30mins. It reached a value of 120GB!


I cannot repro in a new profile. So it could be that my profile is quite messed up.
Comment 16 Girish Sharma [:Optimizer] 2012-11-29 22:08:18 PST
Created attachment 686941 [details]
Task manager screenshot

I am having doubts that the process not being able to end iitself after closing Firefox and the IO Read Byte issue are related.

for me, 25 min into browsing, this is the task manager entries :

Note how large it is for explorer.exe (1.1 TB)
Comment 17 Nicholas Nethercote [:njn] 2012-11-29 22:10:16 PST
BTW, you do realize that it (AFAICT) is a cumulative measure?  I.e. it'll never go down.
Comment 18 Girish Sharma [:Optimizer] 2012-11-29 22:13:37 PST
So the issue here is that IO Read Byte is increasing as you browse ?

That is unavoidable for this add-on. It much like you are viewing your Browsing History, which will also produce the same effect as it will also query the places DB which is on disk as places.sqlite file.

The special case in comment #3 might be of concern, if the reporter is able to reproduce.
Comment 19 mayankleoboy1 2012-11-29 22:18:12 PST
without this addon, for every image in comment #0 , get ~2mb increae.
With this addon, i get ~133mb increase.

Without this addon, for the same set of actions (opening 14 websites) , i get value of ~400mb.
With this addon, ~ 3GB.

just at start, without this addon, value ~50Mb
With this addon : ~450MB.

> So the issue here is that IO Read Byte is increasing as you browse ?

With this addon, it increases exponentially.

>The special case in comment #3 might be of concern, if the reporter is able to >reproduce.

100% reproducible on my profile. But not on a new profile.
Comment 20 Girish Sharma [:Optimizer] 2012-11-29 22:24:53 PST
Then can you please provide the xperf zip file for your profile ?

As I said, when I open the history library (Ctrl Shift H), and view any folder (Today, September or any other), I get a roughly 230 MB of increase, that would be optimized as the query required to geenrate the view for Today or September is time bounded.

When you open any new url in your browser with my add-on enabled, it does a url based query, which will run across the whole places DB and for me, it turns out to be around 320 MB.

So nothing is exponential, its as it should be. But maybe I can do something to bring down that 320 MB a little.
Comment 21 Kris Maglione [:kmag] 2012-11-29 22:28:29 PST
Girish, I haven't looked, but is the places query that you make synchronous? Making synchronous places queries on every page load is known to cause serious performance problems for a lot of users.
Comment 22 Girish Sharma [:Optimizer] 2012-11-29 22:30:39 PST
(In reply to Kris Maglione [:kmag] from comment #21)
> Girish, I haven't looked, but is the places query that you make synchronous?
> Making synchronous places queries on every page load is known to cause
> serious performance problems for a lot of users.

No, its absolutely async.
Comment 23 mayankleoboy1 2012-11-29 22:33:49 PST
in my case, 
1. create a new tab.
2. Go to homepage. (which is google.co.in ). Wait for it to load completely.
3. Close the tab.

This operation takes ~ 400MB.
Comment 24 Girish Sharma [:Optimizer] 2012-11-29 22:35:47 PST
(In reply to mayankleoboy1 from comment #23)
> in my case, 
> 1. create a new tab.
> 2. Go to homepage. (which is google.co.in ). Wait for it to load completely.
> 3. Close the tab.
> 
> This operation takes ~ 400MB.

This might differ depending on the size of places.sqlite file in your profiles directory.

Can you also tell the increase when you view some folder in the History Library ?
Comment 25 mayankleoboy1 2012-11-29 22:42:03 PST
opening history of a complete month, scrolling multiple time from top to bottom, highlighting lots of entries, i get around ~200MB increase.
Comment 26 mayankleoboy1 2012-11-29 22:44:04 PST
(In reply to Girish Sharma [:Optimizer] from comment #20)
> Then can you please provide the xperf zip file for your profile ?

Tell me how to do it. Link in comment #4 wasnt very helpful.
Comment 27 Girish Sharma [:Optimizer] 2012-11-29 23:06:29 PST
(In reply to mayankleoboy1 from comment #25)
> opening history of a complete month, scrolling multiple time from top to
> bottom, highlighting lots of entries, i get around ~200MB increase.

Its the opening history of a complete month part that does the IO, not rest of the operations like scrolling, highlighting.

(In reply to mayankleoboy1 from comment #26)
> (In reply to Girish Sharma [:Optimizer] from comment #20)
> > Then can you please provide the xperf zip file for your profile ?
> 
> Tell me how to do it. Link in comment #4 wasnt very helpful.

Just use the latest Nightly from yesterday (today's one is crashing a lot for me). Download and install xperf as per comment 7, then use the link in comment 4, while running the Nightly like the following instructions :

1. Create a file named "file.bat" and paste the following contents into it

@echo off

xperf -on PROC_THREAD+LOADER+CSWITCH+FILENAME+FILE_IO+FILE_IO_INIT+DRIVERS -f kernel.etl -stackwalk CSwitch+DiskReadInit+DiskWriteInit+DiskFlushInit+FileCreate+FileCleanup+FileClose+FileRead+FileWrite -BufferSize 1024 -MaxBuffers 1024 -MaxFile 1024 -FileMode Circular

echo Reproduce the problem now, hit any key to finish, collect Merged Etl file

pause

echo merging etl...

xperf -d XperfSlowIOcir.etl

@echo on

2. Save it and keep it ready to be double clicked.
3. Start the Nightly you just downloaded as mentioned above. 
4. Double click on the "file.bat" file to run it. It opens up a command prompt.
5. Do the things that you know will increase the IO Read Byte.
6. When you have high IO Read Byte, go to the command prompt opened by the file, and press any key.
7. The etl extension file will be saved in the same folder where your "file.bat" was present.
8. zip it and upload it here.
Comment 28 mayankleoboy1 2012-11-30 00:36:56 PST
http://www.2shared.com/file/u2U3_LvF/XperfSlowIOcir.html

18Mb in size
Comment 29 mayankleoboy1 2012-11-30 00:44:56 PST
i reproduced comment #3 in the above xperf file.
Comment 30 André Ziegler 2012-11-30 01:32:02 PST
(In reply to mayankleoboy1 from comment #28)
> http://www.2shared.com/file/u2U3_LvF/XperfSlowIOcir.html
> 
> 18Mb in size

firefox reads the places.sqlite file very often:

https://dl.dropbox.com/u/5749744/Bilder/xperf/bugzilla.mozilla.org/mayankleoboy1%40yahoo.com/Firefox_IO_places.png

But File IO doesn't mean that there is also disk IO. Windows first tries to satisfy the request from the Cache.

So add '+DISK_IO+CC' after DRIVERS and create a new trace.
Comment 31 mayankleoboy1 2012-11-30 01:44:21 PST
"xperf: error: NT Kernel Logger: Invalid flags. (0x3ec). "

Removing CC fixes it. You want me to run it without CC ?
Comment 32 André Ziegler 2012-11-30 01:48:54 PST
hmm, ok. If this doesn't work use at least the DISK_IO flag. I want to see if the File IO really causes DISK IO or not.
Comment 33 Girish Sharma [:Optimizer] 2012-11-30 01:49:54 PST
(In reply to André Ziegler from comment #32)
> hmm, ok. If this doesn't work use at least the DISK_IO flag. I want to see
> if the File IO really causes DISK IO or not.

How are you viewing the file ?
Comment 34 mayankleoboy1 2012-11-30 01:56:18 PST
Gecko profiler profile : http://people.mozilla.com/~bgirard/cleopatra/#report=4fdf5cb360e685c9d5df1185e909695ebb8e3fb7&mergeUnbranched=true&invertCallback=true

reproducing comment #3 , where firefox uses 100% CPU (25% on my quad core).
Comment 35 André Ziegler 2012-11-30 02:04:02 PST
(In reply to Girish Sharma [:Optimizer] from comment #33)
> (In reply to André Ziegler from comment #32)
> > hmm, ok. If this doesn't work use at least the DISK_IO flag. I want to see
> > if the File IO really causes DISK IO or not.
> 
> How are you viewing the file ?

I look at the file with xperfview which is part of the Windows Performance Tollkit.
Comment 36 André Ziegler 2012-11-30 02:06:59 PST
(In reply to mayankleoboy1 from comment #34)
> Gecko profiler profile :
> http://people.mozilla.com/~bgirard/cleopatra/
> #report=4fdf5cb360e685c9d5df1185e909695ebb8e3fb7&mergeUnbranched=true&invertC
> allback=true
> 
> reproducing comment #3 , where firefox uses 100% CPU (25% on my quad core).

if you add +PROFILE after DISK_IO and at the end of the flags after -stackwalk (before -buffersize) I can also see the callstack of the high CPU usage.

Attention. This requires that DisablePagingExecutable is set to 1 in the registry.
Comment 37 mayankleoboy1 2012-11-30 02:10:47 PST
http://www.2shared.com/file/GqxXQde6/XperfSlowIOcir.html

xperf with DISK_IO added.
8mb in size.


(In reply to André Ziegler from comment #36)
> > if you add +PROFILE after DISK_IO and at the end of the flags after
> -stackwalk (before -buffersize) I can also see the callstack of the high CPU
> usage.
> 
> Attention. This requires that DisablePagingExecutable is set to 1 in the
> registry.

 like this ?

@echo off

xperf -on PROC_THREAD+LOADER+CSWITCH+FILENAME+FILE_IO+FILE_IO_INIT+DRIVERS+DISK_IO+PROFILE -f 

kernel.etl -stackwalk CSwitch+DiskReadInit+DiskWriteInit+DiskFlushInit+FileCreate+FileCleanup

+FileClose+FileRead+FileWrite+PROFILE -BufferSize 1024 -MaxBuffers 1024 -MaxFile 1024 -FileMode 

Circular

echo Reproduce the problem now, hit any key to finish, collect Merged Etl file

pause

echo merging etl...

xperf -d XperfSlowIOcir.etl

@echo on
Comment 38 mayankleoboy1 2012-11-30 02:22:49 PST
http://www.2shared.com/file/rMZ7QQgQ/XperfSlowIOcir.html

xperf with the above code.
Comment 39 André Ziegler 2012-11-30 03:29:55 PST
yes it worked. The CPU usage is also related to the SQLite operations:

https://dl.dropbox.com/u/5749744/Bilder/xperf/bugzilla.mozilla.org/mayankleoboy1%40yahoo.com/firefox_cpu.png

The LIKE operation of SQLite seems to be CPU expensive.

Now to the disk IO. What I already thought becomes true, the File read operations don't cause disk IO:

https://dl.dropbox.com/u/5749744/Bilder/xperf/bugzilla.mozilla.org/mayankleoboy1%40yahoo.com/firefox_disk_file_IO.png

During the reads you don't have disk IO causes by Firefox.

So the question is why is the addon doing so much SQLite calls to places and how can the storage team reduce the SQLite CPU consumption in the LIKE operator.
Comment 40 Girish Sharma [:Optimizer] 2012-11-30 03:36:51 PST
(In reply to André Ziegler from comment #39)
> yes it worked. The CPU usage is also related to the SQLite operations:
> 
> https://dl.dropbox.com/u/5749744/Bilder/xperf/bugzilla.mozilla.org/
> mayankleoboy1%40yahoo.com/firefox_cpu.png
> 
> The LIKE operation of SQLite seems to be CPU expensive.

I use LIKE for url matching. If that is the bottleneck, i should think of a workaround for now.

> Now to the disk IO. What I already thought becomes true, the File read
> operations don't cause disk IO:
> 
> https://dl.dropbox.com/u/5749744/Bilder/xperf/bugzilla.mozilla.org/
> mayankleoboy1%40yahoo.com/firefox_disk_file_IO.png
> 
> During the reads you don't have disk IO causes by Firefox.
> 
> So the question is why is the addon doing so much SQLite calls to places 

Because that is my add-on's features. Display url sin breadcrumbs display and so on each url change, I have to look up in the places to see if the last breadcrumb should be pointed or flat. Pointed means that there are possible urls in the child directory, while flat means that you did not ever go any further in the url as per breadcrumb heirarchy. For ex if you visit facebook firest time, it will be flat. But lets say you visit your profile and now you go back to facebook.com, then the breadbrumb for facebook.com will not be flat, it will be arrow, representing that you have gone further inside in hierarchy, so when you click that arrow, you will get the list of urls visited. 
But at time of url change, only the query to get the count of similar urls is done to places.
 
> how can the storage team reduce the SQLite CPU consumption in the LIKE
> operator.

maybe getting some involved poeple to this bug will help.
(if you are not already involved in the corresponding team)
Comment 41 mayankleoboy1 2012-11-30 03:48:19 PST
I find that if you switch between two tabs, the addon always does some I/O.
So if you open three images in three tabs like these :

1.http://orangoo.com/labs/greybox/static_files/salt.jpg
2.http://www.artsjournal.com/artopia/seance,jpg.jpg
3.http://thickbox.net/images/plant4.jpg

and press and hold "ctrl+tab" , you can see that the CPU usage increases and the i/o starts increasing. If you keep holding ctrl+tab for about a minute, it would seem that the IO value kees on increasing unbound.
Comment 42 mayankleoboy1 2012-11-30 03:54:14 PST
instead of opening the above URL's , search google images for anything and open images from there. Then while images are being loaded, press and hold "ctrl +tab".

Or open 5-6 tabs from a site you visit a lot. then press and hold ctrl+tab.
Comment 43 Girish Sharma [:Optimizer] 2012-11-30 03:55:49 PST
(In reply to mayankleoboy1 from comment #41)
> I find that if you switch between two tabs, the addon always does some I/O.
> So if you open three images in three tabs like these :
> 
> 1.http://orangoo.com/labs/greybox/static_files/salt.jpg
> 2.http://www.artsjournal.com/artopia/seance,jpg.jpg
> 3.http://thickbox.net/images/plant4.jpg
> 
> and press and hold "ctrl+tab" , you can see that the CPU usage increases and
> the i/o starts increasing. If you keep holding ctrl+tab for about a minute,
> it would seem that the IO value kees on increasing unbound.

I agree that there should be some optimizations done while so frequent tab switching. But IO value does not keeps increasing unbounded. It comes down to rest and that depends on how long you pressed the Ctrl TAB combination and due to that how many times tab changed ..
Comment 44 Girish Sharma [:Optimizer] 2012-11-30 03:59:49 PST
Please refer to issue 62 [1] for further information from my side on the codebase.
This bug should be now kept to investigate if anything can be done to improve sql queries (like LIKE etc). Feel free to change the status accordingly.

[1] https://github.com/scrapmac/UIEnhancer/issues/62
Comment 45 mayankleoboy1 2012-11-30 04:19:51 PST
or maybe not do a SQL query on each tab switch ? 
Do SQL only if new tab is opened or if a URL is pasted in a tab and enter is pressed.
Comment 46 Girish Sharma [:Optimizer] 2012-11-30 04:34:12 PST
(In reply to mayankleoboy1 from comment #45)
> or maybe not do a SQL query on each tab switch ? 
> Do SQL only if new tab is opened or if a URL is pasted in a tab and enter is
> pressed.

There are many more cases.
What if user navigates to a new url ?
Comment 47 André Ziegler 2012-11-30 04:51:24 PST
(In reply to Girish Sharma [:Optimizer] from comment #40)
> > 
> > So the question is why is the addon doing so much SQLite calls to places 
> 
> Because that is my add-on's features. Display url sin breadcrumbs display
> and so on each url change, I have to look up in the places to see if the
> last breadcrumb should be pointed or flat. Pointed means that there are
> possible urls in the child directory, while flat means that you did not ever
> go any further in the url as per breadcrumb heirarchy. For ex if you visit
> facebook firest time, it will be flat. But lets say you visit your profile
> and now you go back to facebook.com, then the breadbrumb for facebook.com
> will not be flat, it will be arrow, representing that you have gone further
> inside in hierarchy, so when you click that arrow, you will get the list of
> urls visited. 
> But at time of url change, only the query to get the count of similar urls
> is done to places.
>  

ok, thanks for the explanation what your addon does.

> maybe getting some involved poeple to this bug will help.
> (if you are not already involved in the corresponding team)

I'm not involved in Firefox, I only read his comment in the Memshrink blog of Nicholas.
Comment 48 Nicholas Nethercote [:njn] 2012-11-30 05:00:56 PST
This arguably shouldn't even be a bug in bugzilla.mozilla.org.  General issues with an add-on X should be handled by whatever mechanism add-on X specifies -- it's own bug tracker, email, whatever.

(There are some exceptions, e.g. we've been tracking memory leaks in add-ons, but this doesn't fall into that category.)
Comment 49 Girish Sharma [:Optimizer] 2012-11-30 05:02:52 PST
(In reply to Nicholas Nethercote [:njn] from comment #48)
> This arguably shouldn't even be a bug in bugzilla.mozilla.org.  General
> issues with an add-on X should be handled by whatever mechanism add-on X
> specifies -- it's own bug tracker, email, whatever.
> 
> (There are some exceptions, e.g. we've been tracking memory leaks in
> add-ons, but this doesn't fall into that category.)

I created the issue for this very purpose.

@Everyone else, please continue discussion over there.
Comment 50 Girish Sharma [:Optimizer] 2012-12-01 07:00:49 PST
FWIW, fixing of issue [54] made it possible to remove the excess i/o done by the addon on every url change (issue [62]) and now the i/o is normal. This will be in version 5.1. Hence, closing this bug.

[54] https://github.com/scrapmac/UIEnhancer/issues/54
[62] https://github.com/scrapmac/UIEnhancer/issues/62

Note You need to log in before you can comment on or make changes to this bug.