1269953 - [Perf][google docs] 12.43%(2733 ms) slower than Chrome when opening 1 page table and delete all

Status: RESOLVED WONTFIX

(Core :: General, defect)

Description

[Shako Ho]

# Test Case
STR
1. Launch the browser with blank page
2. input the google doc url with 1 table content
3. delete all tables
4. close the browser

# Hardware
OS: Ubuntu 14.04 LTS 64-bit
CPU: i7-3770 3.4GMhz
Memory: 16GB Ram
Hard Drive: 1TB SATA HDD
Graphics: GK107 [GeForce GT 640]/ GF108 [GeForce GT 440/630]

# Browsers
Firefox version: 45.0.2
Chrome version: 50.0.2661.75

# Result
Browser | Run time (median value) 
Firefox | 24727.7777 ms
Chrome  | 21994.4444 ms

Comment 1

[Cynthia Tang [:cynthiatang]]

# Test Case
 1. Launch the browser with blank page
 2. Input the google doc url with 1 pages table content
    https://goo.gl/ASWnsK
 3. Close the browser
 
# Profiling Data:
https://cleopatra.io/#report=5051a31c6200c04f33d15edcd19a2c5e3d5219c1

# Performance Timing:
http://goo.gl/fl69o0
{ 
  "navigationStart": 1463041513000, 
  "unloadEventStart": 0, 
  "unloadEventEnd": 0, 
  "redirectStart": 0, 
  "redirectEnd": 0, 
  "fetchStart": 1463041513004, 
  "domainLookupStart": 1463041513004, 
  "domainLookupEnd": 1463041513004, 
  "connectStart": 1463041513004, 
  "connectEnd": 1463041513004, 
  "requestStart": 1463041513007, 
  "responseStart": 1463041513392, 
  "responseEnd": 1463041513392, 
  "domLoading": 1463041513396, 
  "domInteractive": 1463041514069, 
  "domContentLoadedEventStart": 1463041514933, 
  "domContentLoadedEventEnd": 1463041514934, 
  "domComplete": 1463041517264, 
  "loadEventStart": 1463041517264, 
  "loadEventEnd": 1463041517270
}

# Orginal Test Script:
https://github.com/Mozilla-TWQA/Hasal/blob/master/tests/test_firefox_gdoc_read_basic_image_1.sikuli/test_firefox_gdoc_read_basic_image_1.py

# Add profilerMark_3() and Add profilerMark_4():
  sys.path.append(sys.argv[2])
  import browser
  import common
  import gdoc
 
  com = common.General()
  ff = browser.Firefox()
  gd = gdoc.gDoc()
 
  ff.clickBar()
  ff.enterLink(sys.argv[3])
  sleep(5)
  gd.wait_for_loaded()
 
  # Select all
  ff.profilerMark_3()
  type("a", Key.CTRL)
  ff.profilerMark_3()
 
  sleep(0.3)
  
  # Delete all
  ff.profilerMark_4()
  type(Key.DELETE)
  ff.profilerMark_4()
 
  gd.deFoucsContentWindow()

Comment 2

[Cynthia Tang [:cynthiatang]]

Attachment: test_firefox_gdoc_delete_basic_table_1_1463042348.har

Sorry! Correct the profiler data and add the HAR file.
https://cleopatra.io/#report=72f6f995c1ed9d2507b1343bc04dd3c9cdcc90ef

Comment 3

[Cynthia Tang [:cynthiatang]]

# Try to identify the time between "navigationStart" and "loadEventEnd"

Perf Timing:
navigationStart to loadEventEnd = 8392 ms
domLoading to loadEventEnd: 8392 - 407 = 7985 ms
AddOn Start to End mark: 41676 - 33763 = 7913 ms

Profiler: 
https://cleopatra.io/#report=72f6f995c1ed9d2507b1343bc04dd3c9cdcc90ef&filter=[{"type"%3A"RangeSampleFilter","start"%3A33184,"end"%3A41775}]

From Gecko Profiling data, the Range [32487, 41676]:
 8540  100.0%  Startup::XRE_Main
 2329   27.3%  ├─ nsHtml5TreeOpExecutor::RunFlushLoop
 2151   25.2%  │  ├─ nsJSUtils::EvaluateString 
  150    1.8%  │  ├─ EventDispatcher::Dispatch
               │  └─ ...so on
               │
 1742   20.4%  ├─ nsInputStreamPump::OnInputStreamReady
 1570   18.4%  │  ├─ nsInputStreamPump::OnStateStop  
  119    1.4%  │  ├─ nsInputStreamPump::OnStateStart
               │  └─ ...so on
               │
 1380   16.2%  ├─ nsRefreshDriver::Tick
  470    5.5%  │  ├─ PressShell::Flush (Flush_Style)
  428    5.0%  │  ├─ PressShell::Paint
               │  └─ ...so on
               │
 1125   13.2%  ├─ Timer::Fire
 1096   12.8%  │  ├─ js::RunScript
               │  └─ ...so on
               └─ ...so on
Note 
 1. Filed Bug 1270351 for tracking "nsJSUtils::EvaluateString"
 2. Filed Bug 1267971 for tracking "nsInputStreamPump::OnStateStop"
 3. Filed Bug 1270427 for tracking "nsRefreshDriver::Tick"
 4. Filed Bug 1271914 for tracking "js::RunScript"

Comment 4

[Cynthia Tang [:cynthiatang]]

# Try to identify the time for the action "Select All". 
  
You can see profilerMark_3(): 49998 - 49467 = 531 ms

Profiler: https://goo.gl/z6NzWC

From Gecko Profiling data, the Range [49457, 50008]:
 550  100.0% Startup::XRE_Main
 407   74.0% ├─ nsViewManager::DispatchEvent
 401   72.9% │  ├─ EventDispatcher::Dispatch
             │  └─ ...so on
             └─ ...so on

Note: Filed Bug 1273080 for tracking "EventDispatcher::Dispatch"

Comment 5

[Cynthia Tang [:cynthiatang]]

# Try to identify the time for the action "Delete All"

profilerMark_4() is for the action “Delete All”: 50305 - 50021 = 284 ms

Profiler: https://goo.gl/mDDYKj

From Gecko Profiling data, the Range [50001, 50315]:
 313  100.0% Startup::XRE_Main
 177   56.5% ├─ nsViewManager::DispatchEvent
 177   56.5% │  └─ EventDispatcher::Dispatch
             │     └─ ...so on
             └─ ...so on
             
Note: Filed Bug 1273082 for tracking "EventDispatcher::Dispatch"

Comment 6

[Cynthia Tang [:cynthiatang]]

The right test script:
https://github.com/Mozilla-TWQA/Hasal/blob/master/tests/test_firefox_gdoc_delete_basic_table_1.sikuli/test_firefox_gdoc_delete_basic_table_1.py

Comment 7

[Bobby Chien]

Mark as minor case, and marked wontfix in this iteration. Revisit here if necessary.

This bug fixing iteration will focus on critical bug 1264535, bug 1269666, bug 1269684, bug 1269690, bug 1269695, bug 1269698.