Profiling Interactive Response Time For Common User Actions

Evolution/User:Vivek: Out of the User actions listed on the main page, I have picked some and have collected data for the time it takes to complete the operations. For now I am using GTimer to record the time elapsed between the function call after (clicking) and when the function returns. Need to come up with more sensible method to measure the time. I will keep adding the data for more actions here. (Time measured is in seconds)

Machine details where the data is collected:

 model name      : Intel(R) Pentium(R) 4 CPU 1.80GHz
 cpu MHz         : 1794.793
 cache size      : 256 KB

 Mem (KB):        total: 516012    used: 502976
 Swap(KB):        total:1048816    used: 612980

Opening the mail composer window after "New Mail" is clicked

Noticing that while opening the composer window, we load addressbooks marked for autocompletion, I collected the time for three different cases:

 A) 'All' the addressbooks are marked for autocompletion (I had 6 addressbooks selected).
 B) No addressbook is selected for autocompletion.
 C) After commenting the code that loads the addressboook, while creating the composer window.

Taken 10 readings for each of the cases. Each case is tested after re-starting evolution. But subsequent readings of 'a case' is taken with simply invoking composer again and again.

Data (Time in Sec.)

Case: A

 1.404383               
 0.656810
 0.698204
 0.742127
 0.720384
 0.634934
 0.736810
 0.702350
 0.590535
 0.728095

 Min 0.590535
 Max 1.404383
 Avg(Max+Min)/2
     0.997459

Case B:

 0.980265
 0.544198
 0.635277
 0.629086
 0.652344
 0.666975
 0.620325
 0.671223
 0.695792
 0.660313

 Min 0.544198
 Max 0.980265
 Avg 0.762231

Case C:

 1.215054
 0.622408
 0.481829
 0.534799
 0.657402
 0.623716
 0.533689
 0.519728
 0.516353
 0.562045

 Min 0.481829
 Max 1.215054
 Avg 0.898441

Switching between the folders

Clicking on the INBOX in 'IMAP' after restarting the evolution 1600 mails, 252 unread Data time taken in Seconds.

 5.072854
 4.126351
 5.034218
 4.712634

Clicking on CALENDAR after restaring evo [IMAP] 152 appointments 6 unread

 1.564864
 1.563789
 1.556623
 1.563483

Clicking on any other folder for the first time after restart

 1.123955
 1.155432
 1.362223
 1.243213

Switching between these folders afterwards

 0.131104 to Inbox
 0.236076 to calendar
 0.24040 to Inbox
 0.221467 to calendar
 0.251030 to other folder
 0.117429 to Inbox

Traversing the mails using "Next" and viewing the mail in the preview pane

 IMAP         GROUPWISE

 Mails with No attachments 
 0.7307        1.9156
 0.7343        1.9153 
 0.5445        1.7898
 0.4588        1.7118
 0.4638        2.0049
 0.5557        1.9430
 0.4807        3.8024
 0.6735        1.9975
 0.5393        2.0231
 0.7288        1.8284

 Mails with attachments (small patches as attachments)
 1.8669        1.8298
 1.7787        3.9911
 1.7595        1.7989
 0.5492        1.7095
 0.6674        1.8175  
 0.6085        3.0348
 0.5308        3.1903
 0.8600        1.9887
 0.5203        2.1846
 0.6620        2.4620

 Mails which appear in itip formatter (appointments)
 1.1092
 1.3559
 1.3426
 0.9975
 1.3057
 1.6302
 1.2084

Double click on the mail and the mail appears in message browser window

Checked with groupwise provider and mails having no attachments: Time in sec.

 1.4505
 0.8272
 0.6873
 0.7974
 0.8876
 0.8843
 1.3482
 1.3593

Mails with attachments: (it varies with the size of attachment)

 1.98405 
 3.16192
 6.25081

Deleting a mail and getting the next mail in the preview pane

 IMAP         GROUPWISE

 When 'Hide deleted messages' is off
 0.9597       0.9224
 0.6485       2.1113
 0.6655       1.8066
 0.6548       1.6597
 0.9898       1.3028
 0.9569       1.6871
 0.8111       1.7539  
 0.6104       1.6645  
 0.5531       1.6304
 0.5695       2.5560 

When 'Hide Deleted messages' is on

 1.3523       0.9718
 1.4839       1.0951
 1.2059       2.5780
 0.6141       1.3663
 1.0086       1.5296
 1.5112       1.3183

Deleting 10+ mails and getting the next mail in the preview pane

 IMAP         GROUPWISE

 When 'Hide deleted messages' is off
 1.1539
 2.3846
 1.9168

 When 'Hide deleted messages' is on

Moving 10+ mails

This opearation is done in another thread, still I have measured the time it took to complete the operation. Have taken two cases, just to see how GUI updation makes a difference.

                  GROUPWISE  
  
 When 'Hide deleted messages' is OFF
                 1.36847  (10 mails)
                 2.40063  (20 mails) 
                 3.50414  (30 mails)
                 4.49523  (40 mails)
                 5.84039  (50 mails)
                 6.90213  (60 mails)
                 7.98356  (70 mails) 

 When 'Hide deleted messages' is ON
                 1.41296  (10 mails)
                 2.45760  (20 mails) 
                 3.52551  (30 mails)
                 4.89016  (40 mails)
                 5.84029  (50 mails)    
                 6.82270  (60 mails)
                 8.08752  (70 mails)

Switching between the Components

Generally I found it to be fast enough, particularly when the CPU is not very busy. Here is the data I collected when I was switching between Mail, Calendar, Tasks, Contacts (without any particular sequence) I have measured it from the time user clicks on the button to the time that component window appears. However it stops updating GUI only after it has displayed the previously selected folder in that component, which I did NOT count.

(sec.)

 0.29207
 0.75364
 0.99070
 0.17323
 0.44302
 0.23925
 0.16970
 0.11414
 0.14596
 0.43539
 0.23546
 0.14973
 0.17235
 0.15369
 0.44358
 Max = 0.99070
 Min = 0.11414
 Avg (max+Min)/2 = 0.55242

Opening the "New Meeting" dialog after that option is clicked

 0.5435 
 0.5513
 0.5714
 0.5880
 0.5373
 0.5083
 0.5220
 0.5394
 0.5189

In Another Set of executions

 0.6792
 0.5000
 0.8335
 0.5501
 0.5923
 0.5686

Yet another Set

 0.9726
 0.7193
 0.7148
 0.7324
 0.7471
 0.7800
 0.7342
 0.7617
 0.5491
 0.5446 

Saving the Meeting (Sending it)

In the case of file backend invitations to the participants are sent by us and that makes small difference in time taken, whereas in groupwise its server which sends the invitations.

 GROUPWISE         PERSONAL (File) 
 0.1071             0.6544
 0.1005             0.6382       
 0.0922             0.6642 
 0.1045             0.6557
 0.1049             0.6359
 0.1091             0.6038
 1.3864             0.5965
 0.1007             1.7009

Time taken by "Send/Receive" to complete

Shows significance difference in the time taken for this operation in IMAP and groupwise. I tested this with my corporate account (against wal-3 server)

  IMAP              GROUPWISE

 8.7552             38.0492  
 6.3048             36.6666  
 5.8899             37.5276
 7.2373             39.2257
 5.8248             37.1481
 7.0769             14.9826
 5.6655             14.1791
 5.8041             14.8531 
 6.4607             39.1705
 6.2940             18.0090 
 6.2736             18.4245
 6.4805             21.6151

Auto-completion [Groupwise system addressbook]

 This is the data on Novell groupwise system addressbook (wal-3)
 Minimum query length is 3 

Time Taken in seconds

The behavior is very inconsitent, the first 5 listed here are the time taken to get the results when I typed three characters

 3.064825
 2.270263
 1.554715
 1.549043
 1.402025

The Following pair represents the total time taken, first part is time taken to query for the three characters I typed, second part (after +) is to complete the query for four characters, its only after typing 4 characters i could see the results.

 0.983519 + 1.501010
 0.925388 + 0.939652
 1.006928 + 0.992606
 0.968489 + 0.973318
 1.002339 + 0.983255
 1.016767 + 1.866121
 1.349487 + 1.223308
 4.468377 + 1.535511

Searching a contact

GROUPWISE PERSONAL ADDRESSBOOK (with 512 contacts)

Time in seconds:

 NULL query:
 2.5945

 single character [found 5 results]
 0.4427
 0.4699

 single character [found 26 results]
 0.5587
 0.5635
 
 single character [found 449 contacts]
 2.2856
 2.3614
 2.2889

GROUPWISE SYSTEM ADDRESSBOOK (wal-3 account)

 Search finds 5-6-7 results (normally entering almost full name or 3-4 characters)
 1.0171
 1.0863
 1.2957
 
 Search finds 40 results
 2.7262
 
 Search finds 80 results
 4.2651
 
 Enter Single character and search finds 331 results (less likely a scenario)
 63.8455

FILE [PESRONAL] ADDRESSBOOK WITH 480 CONTACTS

 loading that/ performing "null" query takes
 1.4739
 1.6273
 1.3635
 1.2738
 
 Serach finds 55 contacts
 0.4649
 Search finds 115 contacts
 0.5992
 0.6086

Loading the Calendar Items

This test is done on my groupwise calendar on wal-3 (groupwise server). The calendar contained 376 appointments (all cached). The results are taken by restarting evo again and again

A = time taken to get the first set of results to display B = Total time taken for entire calendar to load

 1. A = 12.215422   B = 19.256214
 2. A.= 11.011243   B = 22.666659
 3. A = 21.15800    B = 65.70593  (Not sure why it was so slow here)
 4. A = 10.615620   B = 16.215257
 5. A = 10.179308   B = 17.215624

Apps/Evolution/Evo2.4/Profile_data (last edited 2013-08-08 22:50:00 by WilliamJonMcCann)