426991 - Form submission extremely slow on large forms (with form history turned on)

Status: RESOLVED FIXED

(Toolkit :: Form Manager, defect)

Description

[Karel Kolman]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9b5) Gecko/2008032620 Firefox/3.0b5
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9b5) Gecko/2008032620 Firefox/3.0b5

When submitting a form with many inputs, it takes a long time before the entered values are crunched by form history manager and form submission actually happens.
I have a 120+ inputs form, it takes 10 second before request is sent to the form action target url. I have a not-so-fast Sempron 2400+ system with an old hard disk. I hear heavy disk activity after clicking the Submit button.

Resubmitting the same form is fast. Clearing the form history (through Clear private data) and resubmitting the form takes a long time again.

Reproducible: Always

Steps to Reproduce:
1. Open a page with a form with many inputs in the browser.
2. Clear private data history.
3. Submit the form.
4. Submit the form again.
Actual Results:  
Step 3. takes way too long to finish.
Step 4. finishes quickly.

Expected Results:  
A previously not submitted form with many inputs will take only slightly more time to submit than subsequent submissions of the same form.

Comment 1

[Karel Kolman]

Attachment: A form with 100+ inputs.

A form with 100+ inputs (post action to the same file).
It takes 10+ seconds on my system to submit.
The formhistory.sqlite db has 9216 bytes when submitting in a clean profile.

Comment 2

[Karel Kolman]

Created a profile on the same system but located on a much faster sata disk, the initial form submission delay is a bit noticeable but generally much shorter (around 1 sec). 

Comment 3

[KenLai]

I met the same problem. 
web form has about 1000 input fields

environment                           resullt
firefox 2.0.0.14 + win xp             ok(1 sec)
firefox 3.0 + winxp                   slow(above 20 secs)
firefox(v2 or v3)+ win2000            very slow(above 30secs). 

Comment 4

[Justin Dolske [:Dolske]]

Yeah, yikes, something crazy is going on here. Submitting the testcase from comment 1 results in 1748 disk operations for formhistory. :-O A small segment from a typical rwsnoop run on my OS X box looks like:

# rwsnoop -vp 44159
TIMESTR                UID    PID CMD          D   BYTES FILE
...
Sep  6 14:51:45   501  44159 firefox-bin  W      24 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W       1 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W       4 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W    1024 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W       4 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W       4 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W    1024 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W       4 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W       4 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W    1024 formhistory.sqlite
Sep  6 14:51:45   501  44159 firefox-bin  W    1024 formhistory.sqlite
Sep  6 14:51:45   501  44159 firefox-bin  W       4 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W    1024 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W       4 formhistory.sqlite-journal
Sep  6 14:51:45   501  44159 firefox-bin  W       4 formhistory.sqlite-journal
...

Comment 5

[Justin Dolske [:Dolske]]

Looks like we create a transaction and execute a statement for *each* form field that's saved. I'm going to go out on a limb and guess that's not the most efficient way to be doing things. :-)

Comment 6

[Shawn Wilsher :sdwilsh]

(In reply to comment #5)
> Looks like we create a transaction and execute a statement for *each* form
> field that's saved. I'm going to go out on a limb and guess that's not the most
> efficient way to be doing things. :-)
No, and that'd be why you hit the perf issue!

I'm not sure where this code lives, but this sounds like a prime candidate to use the async storage API too!

Comment 7

[Justin Dolske [:Dolske]]

Attachment: Patch v.1

Fixes the problem by removing the per-entry transaction, and instead using a per-form transaction.

I benchmarked this by measuring the time it takes to execute the for-loop in Notify() [which this patch wraps in a transaction]. Repeated 5 times, deleting formhistory.sqlite in between runs (we short-circuit when the saved value already exists).

In the current code, submitting the attached testcase was measured at 224ms. With this patch, it now takes 8ms. 28x faster, woo! :-)

Looking at the file IO with DTrace, I see a handful of tiny writes to formhistory-sqlite-journal, followed by 8 1K writes to formhistory.sqlite, followed by a few more writes to formhistory-sqlite-journal. Much better than the flood I saw in comment 4.

Comment 8

[Justin Dolske [:Dolske]]

Oh, meant to also note: I also measured the perf with removing the per-entry transaction (but not adding the per-form transaction), and didn't see a significant change in the numbers.

Comment 9

[Shawn Wilsher :sdwilsh]

(In reply to comment #8)
> Oh, meant to also note: I also measured the perf with removing the per-entry
> transaction (but not adding the per-form transaction), and didn't see a
> significant change in the numbers.
What is more interesting in both cases is the number of fsyncs.

Comment 10

[Shawn Wilsher :sdwilsh]

Comment on attachment 342003 [details] [diff] [review]
Patch v.1

>+  transaction.Commit();
> 
>   return NS_OK;
please return the value from transaction.Commit() - it's possible it could fail.

r=sdwilsh with that fixed.

Comment 11

[Justin Dolske [:Dolske]]

Attachment: Patch v.2

Comment 12

[Justin Dolske [:Dolske]]

This fix was included as part of bug 483096.

Comment 13

[Justin Dolske [:Dolske]]

(On 1.9.0.8, that is.)

Comment 14

[Al Billings [:abillings - ex-MoCo]]

Verified through bug 483096 for 1.9.0.8.