Generate system performance data for performance related issues

In some cases it may be necessary to generate system performance data to assist further with analysing what is occurring. Use the following details to generate the performance details:

Prerequisite

Build your client from 'master' and enable support debug symbols:

git clone https://github.com/abraunegg/onedrive.git
cd onedrive
./configure --enable-debug
make clean; make;
sudo make install

Install the application including any debug symbols generated. You may also need to install your Linux Kernel Debug Symbols as well.

Performance data to collect

Number of Online Objects

Firstly, perform a --resync of your data.

During the sync cycle, take note of the following data point:

Processing XXXXXX applicable JSON items received from Microsoft OneDrive

Microsoft recommends storing no more that 300,000 files & folders in a single OneDrive account. If you are getting up towards this number, how and what you store on OneDrive needs to be looked at first.

Secondly, if you are storing items close to this value online, it is going to take time to process this data when performing a full sync. OneDrive sends data to this client in ~200 item lots as a change set (this is hardcoded by Microsoft, there is zero way to change this). A change set will take approx 1-1.5 seconds for this client to process depending on how many items are present in the change set.

Example: If you have 200K items on OneDrive, this means approx 1000 change set bundles will be sent to the client. Assuming 1.5 seconds to process each one = 1500 seconds = potentially 25 minutes to process your online data.

The actual processing time per JSON item received from Microsoft OneDrive for your system is displayed in the application debug logs.

To create an application debug log please read: https://github.com/abraunegg/onedrive/wiki/Generate-debug-log-for-support

Client Function Performance Data

Run the client with the following option set in your 'config' file:

display_processing_time = "true"

This will print important performance related processing timings for each major function the application performs, which will help to drill down what function is potentially causing your performance concern.

When this option is set, to obtain this functional performance information, you must run the client in debug mode (--verbose --verbose) otherwise zero functional level performance data will be displayed.

An example of this output is below:

[alex@onedrive-client-dev]$ ./onedrive -s -v -v --resync --resync-auth | grep 'Application Function' 
DEBUG: [BDrTb27fRL4Hhakv] Application Function 'syncEngine.initialise()' Started
DEBUG: [tZnOohqezNIpv0P3] Application Function 'syncEngine.getDefaultDriveDetails()' Started
DEBUG: [Sc7GWeOR5KwVosJI] Application Function 'syncEngine.addOrUpdateOneDriveOnlineDetails()' Started
DEBUG: [jNOC40cweH61VbhM] Application Function 'syncEngine.getRemainingFreeSpaceOnline()' Started
DEBUG: [jNOC40cweH61VbhM] Application Function 'syncEngine.getRemainingFreeSpaceOnline()' Processing Time = 0.3150 Seconds
DEBUG: [Sc7GWeOR5KwVosJI] Application Function 'syncEngine.addOrUpdateOneDriveOnlineDetails()' Processing Time = 0.3160 Seconds
DEBUG: [tZnOohqezNIpv0P3] Application Function 'syncEngine.getDefaultDriveDetails()' Processing Time = 2.0030 Seconds
DEBUG: [C6BXTLv2oiumhY7G] Application Function 'syncEngine.getDefaultRootDetails()' Started
DEBUG: [RFkD9PqviOHrVhbf] Application Function 'syncEngine.saveItem()' Started
DEBUG: [pdJNSgqbrBwaQKPh] Application Function 'syncEngine.makeItem()' Started
DEBUG: [pdJNSgqbrBwaQKPh] Application Function 'syncEngine.makeItem()' Processing Time = 0.0000 Seconds
DEBUG: [RFkD9PqviOHrVhbf] Application Function 'syncEngine.saveItem()' Processing Time = 0.0030 Seconds
DEBUG: [C6BXTLv2oiumhY7G] Application Function 'syncEngine.getDefaultRootDetails()' Processing Time = 0.8590 Seconds
DEBUG: [BDrTb27fRL4Hhakv] Application Function 'syncEngine.initialise()' Processing Time = 2.8630 Seconds
DEBUG: [zh5IKgSdC3mGA9tB] Application Function 'syncEngine.clearInterruptedSessionUploads()' Started
DEBUG: [zh5IKgSdC3mGA9tB] Application Function 'syncEngine.clearInterruptedSessionUploads()' Processing Time = 0.0000 Seconds
DEBUG: [NUp58MquoOglLh3A] Application Function 'syncEngine.syncOneDriveAccountToLocalDisk()' Started
DEBUG: [9dFaE5YfiWOmtLQX] Application Function 'syncEngine.fetchOneDriveDeltaAPIResponse()' Started
DEBUG: [Qh7MJlrpBTau8dqs] Application Function 'syncEngine.getDeltaLinkFromCache()' Started
DEBUG: [Qh7MJlrpBTau8dqs] Application Function 'syncEngine.getDeltaLinkFromCache()' Processing Time = 0.0000 Seconds
DEBUG: [BuF6pRAxzflsT9dj] Application Function 'syncEngine.getDeltaChangesByItemId()' Started
DEBUG: [BuF6pRAxzflsT9dj] Application Function 'syncEngine.getDeltaChangesByItemId()' Processing Time = 0.8770 Seconds
DEBUG: [BfMLWAyY5RIcNZtk] Application Function 'syncEngine.processDeltaJSONItem()' Started
....

CPU Information

cat /proc/cpuinfo

Memory Information

cat /proc/meminfo

CPU Performance Governance

cat /sys/devices/system/cpu/cpu0/cpufreq/scaling_available_governors
cat /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor

Disk I/O

Run for at least ~30 minutes:

iostat -dx 2

Generate an strace

Run strace on the application as it is running in verbose debug mode (see above) with 'display_processing_time' enabled:

ps -AL |grep process_name
strace -c -p <PID>

Example:

[alex@centos7full ~]$ ps -AL | grep onedrive
16753 16753 pts/0    00:00:00 onedrive
[alex@centos7full ~]$ strace -c -p 16753
strace: Process 16753 attached
^Cstrace: Process 16753 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 20.98    0.000823          16        53           nanosleep
 17.31    0.000679         679         1           open
 17.23    0.000676         169         4           sendto
 13.61    0.000534         178         3           stat
 10.32    0.000405           4       102           fcntl
  8.56    0.000336           4        87           poll
  3.77    0.000148           4        38           write
  3.24    0.000127          32         4           fsync
  1.33    0.000052           2        23           lseek
  0.97    0.000038           2        16           recvfrom
  0.59    0.000023          12         2           close
  0.54    0.000021          21         1           unlink
  0.46    0.000018           9         2           read
  0.41    0.000016           8         2         1 access
  0.25    0.000010           3         4           fstat
  0.18    0.000007           7         1           restart_syscall
  0.10    0.000004           2         2           getdents
  0.10    0.000004           4         1           openat
  0.05    0.000002           1         4           lstat
------ ----------- ----------- --------- --------- ----------------
100.00    0.003923                   350         1 total

Generate system performance profile

Run perf on the application as it is running in verbose debug mode (see above) with 'display_processing_time' enabled:

ps -AL |grep process_name
perf top --call-graph dwarf --pid <PID>