Closed Bug 814942 Opened 12 years ago Closed 12 years ago

Excessive I/O read bytes with addon location bar enhancer

Categories

(WebExtensions :: General, defect)

Product:
WebExtensions
Component:
General
Platform:
x86_64
Windows 7
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: mayankleoboy1, Unassigned)

References

(
URL
)

Details

Attachments

(2 files)

stats after 30mins of browsing.
79.19 KB, image/png
Details
Task manager screenshot
25.26 KB, image/png
Details 
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.
Stats after 30 mins of web browsing.
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.
URL: http://screenr.com/swS7
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.
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.
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.
Component: Untriaged → Add-ons
Product: Firefox → Tech Evangelism
Version: 20 Branch → unspecified
"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.
CCing developer.
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 ?
Flags: needinfo?(n.nethercote)
Flags: needinfo?(mayankleoboy1)
again, make the xperf trace while you think you have this issue.
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.
>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.
Flags: needinfo?(mayankleoboy1)
> >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...
Flags: needinfo?(n.nethercote)
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.
Attached image 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)
BTW, you do realize that it (AFAICT) is a cumulative measure?  I.e. it'll never go down.
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.
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.
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.
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.
(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.
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.
(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 ?
opening history of a complete month, scrolling multiple time from top to bottom, highlighting lots of entries, i get around ~200MB increase.
(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.
(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.
i reproduced comment #3 in the above xperf file.
(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.
"xperf: error: NT Kernel Logger: Invalid flags. (0x3ec). "

Removing CC fixes it. You want me to run it without CC ?
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.
(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 ?
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).
(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.
(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.
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
http://www.2shared.com/file/rMZ7QQgQ/XperfSlowIOcir.html

xperf with the above code.
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.
(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)
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.
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.
(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 ..
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
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.
(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 ?
(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.
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.)
(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.
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
Status: UNCONFIRMED → RESOLVED
Closed: 12 years ago
Resolution: --- → FIXED
Component: Add-ons → General
Product: Tech Evangelism → WebExtensions
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: