New issue
Advanced search Search tips

Issue 796741 link

Starred by 1 user

Issue metadata

Status: Untriaged
Owner: ----
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

Significant jump in io activity in R58, WriteSectorsShort

Project Member Reported by asavery@chromium.org, Dec 20 2017

Issue description

There is a significant jump in R58 in io activity, specifically the 99% percentile of the instaneous IO load doubled: 

https://uma.googleplex.com/p/chrome/timeline_v2/?sid=e7743122c922d88bfd12220e0315afcb

I ran telemetry_Benchmarks.page_cycler_v2.typical_25 on a lulu, with R57-9202.64.0 and R58-9334.74.0. Looking at the change in the /sys/block/sda/stat output from before and after the test, there is a significant increase in write sectors in R58.  For example, we see 1055616 write sectors as the test runs on R58 compared to 233696 write sectors in R57.

I am attaching graphs showing some of the differences in the /sys/block/sda/stat outputs, with a few different values for R57 and R58 to show potential variations across test runs.

I am also attaching ftrace outputs, filtered for syncs and vfs_writes, showing activity during the test run.

This comes from comment 5 on  crbug.com/712166 
 
write_ios.png
12.0 KB View Download
write_merges.png
11.8 KB View Download
write_sectors.png
11.7 KB View Download
ftrace_out.tar.gz
996 KB Download
Running more of the telemetry_Benchmarks.page_cycler_v2.typical_25 test on a lulu and looking at write sectors in the /sys/block/sda/stat output within R58, it jumps from 268152 in R58-9334.56.0 to 991984 in R58-9334.57.0. Looking at the diff, it seems that this change: https://chromium.googlesource.com/chromiumos/third_party/kernel/+/3430305a1b879752779dda0cc72db0d72287bb39%5E%21/#F0
is responsible for this increase. Using the release-R58-9334.B branch, I ran the test with the change included and again with the change removed from inode.c. With the change I saw 1052336 write sectors and with the change removed I saw 226360 write sectors. This seems to account for the large increase in write sectors I saw above, but it doesn't fully explain the jump in io activity seen in the graph. At both ends of the jump in io activity there are data points with 57.0.2987.146. It looks like there are only 4 R57 builds that use that chrome version so the change in R58 doesn't seem to explain that.
Looking at the 99th percentile of the WriteSectorsShort metric across multiple milestones: https://uma.googleplex.com/p/chrome/timeline_v2/?sid=6f67296ee1ab9267367031f0a910f65f  we can see that overall there is an increase in the number of disk sectors per second written in R58 and R59, but that in later milestones, specifically in 61 and 62, that number seems to have gone back down. The increase in write sectors in 58 and 59 seems to be a result of the change stated in the comment above. As I described above, I looked at the difference in write sectors in /sys/block/sda/stat from before and after running telemetry_Benchmarks.page_cycler_v2.typical_25 on a lulu. The number of write sectors was between 200,000 and 300,000 before the change and between 1,000,000 and 1,100,000 after the change. Removing the change in R58 shows a return to the 200,000 range. Since the suspected change is an ecryptfs change, we expect it to have a much smaller effect in later milestones as we move to ext4 crypto. We can see that this does seem to be the case, both in the lower values for 61 and 62 in the graph, as well as in the difference in write sectors after the telemetry_Benchmarks.page_cycler_v2.typical_25 test. I ran the test on a lulu with an R65 image and saw 272576 write sectors, which is within the range from before the R58 change. This change in R58 does not explain the R57 jump we see on the graph, but we can see that across the graph there are peaks for all the milestones which seem to be followed by times of low data volume. It is possible that these jumps are related to updates. Looking at a graph of updates, https://omahadashwiki.corp.google.com/custom/?active_days=7&app=CHROME-OS-*&app_pretty=CHROME-OS-*&asterisk_date=2018-01-08&breakout=tag_and_version&bv=*&completion_ratio=0.98000&count=unique&data_category=updates&display_name=28+Day+Checks+By+Platform&height=350&is_crx=false&limit=10&num_days=365&only_formula=true&sort_order=historical_high&start_day=*&style=gviz&width=800  there does seem to be some correlation between updates and these peaks, but I'm not sure if that fully explains it.

In summary, it appears that this change: https://chromium.googlesource.com/chromiumos/third_party/kernel/+/3430305a1b879752779dda0cc72db0d72287bb39%5E%21/#F0 
is responsible for the overall increase in write sectors in R58, but does not explain the peaks that can be seen in the graph across milestones, which seem to be a regular occurrence and could potentially be related to updates. The R58 increase appears to have been caused by a necessary change and we seem to be past its effects.

Comment 3 by osh...@chromium.org, Jan 26 2018

Cc: apronin@chromium.org semenzato@chromium.org
Components: OS>Performance
If https://crrev.com/c/483305 is indeed the one that causes it, then I agree that:
 - we expect it to have a much smaller effect in later milestones as we move to ext4 crypto.
 - The R58 increase appears to have been caused by a necessary change and we seem to be past its effects.

Sign in to add a comment