Impact of debug log on eMMC/flash longevity #168
Description
Describe the bug
Split of #166 which is about if the service is suspended, very minimal I/O and CPU usage should happen.
But when having the service enabled, the ressource usage and emmc/flash wear question is still there. I assume there are a lot of people having it always on. With other apps refreshing maybe too much their notifications. Including audio/video playback bars looking like a common case.
Technical information:
- Voice Notify version: 1.4.4
- Device model: Fariphone 3
- OS: Android 13: LineageOS 20
- Installed from: F-Droid
- App language: french
- Text-To-Speech engine (if applicable): Sherpa
Additional information
Answer to #166 (comment)
This will be quite long. But it's to give enough info to spot eventual mistakes that invalidate parts of the findings. And so other people can get the same data to compare on their phone.
tl;dr To know on your phone how much voice notify writes vs the overall system writes on the eMMC.
# adb shell root or root terminal on phone
# **proofread this ↓ to see that it just read files. Don't blindly run root code.**)
uptime; cat /proc/$(pidof com.pilot51.voicenotify)/io | grep -E "^write_bytes" | awk '{ print "voice notify:" ,$2/1024/1024, "MiB written since boot" }' ; cat /sys/block/mmcblk0/stat | awk '{ print "total system:" ,($7 * 512)/1024/1024, "MiB written since boot" }'
# You might be interested in how much your eMMC is worn out. See commands in the next paragraphs.
There is a rolling debug log with a 1MB limit saved to external storage at Android/data/com.pilot51.voicenotify/files/debug.log, so that would be the source of the I/O usage.
Thanks a lot for confirming the worry :o
Usually the debug log isn't writing so much that it would be a concern for system performance or flash longevity, but there are always edge cases and it would be a good idea for me to add an option to disable debug logging
I'm using https://f-droid.org/packages/jp.takke.cpustats/ since a long time so that might be bad because it's a constant thing that updates it's two notifications. It's like every 5 sec so it's not that spammy. So that doesn't make my phone that much of an outlier. Even without the debug usage I had of Xtra with testing the download process. Regular downloads might still be an issue with the too simple notification update logic that spams it. And I'm not sure that's the only app that handles progress bars like that. Maybe with audio or video players playback bars?
Maybe it's worth counting the data written the debug log file and include that data from time to time in said log. That would allow in unrelated bug report to contribute knowing how much in the wild the app has written since uptime. And confirm how actually rare that could be an issue for flash longevity.
I don't have historical emmc wear data. And much less per process write monitoring that would quantify voice notify contribution. But the current state is this:
(in root shell, two ways on getting the data that work on a Fairphone 3 that has a Qualcomm SOC)
cat /sys/devices/platform/soc/7824900.sdhci/mmc_host/mmc0/mmc0:0001/{life_time,pre_eol_info}
0x0b 0x0b
01
cat /sys/class/mmc_host/mmc0/mmc0\:0001/{life_time,pre_eol_info}
0x0b 0x0b
01
https://wiki.friendlyelec.com/wiki/index.php/EMMC
01 is pre_eol_info and means 0x01 - Normal: consumed less than 80% of the reserved blocks. Cool.
0x0b 0x0b is life time estimation for SLC and MLC eraseblocks.
0x0b => "exceeded its maximum estimated device life time"
😱😱😱😱😱 I really really hope that pre_eol_info will switch to:
0x02 - Warning: consumed 80% of the reserved blocks.
0x03 - Urgent: consumed 90% of the reserved blocks.
Instead of having possible corruption at any time from now.
But that's a risky bet.
Third way if that can help to work on many SoC vendors:
# bash root shell
RES=`cat /sys/kernel/debug/mmc0/mmc0:0001/ext_csd`
typea="${RES:536:2}" ;
typeb="${RES:538:2}" ;
typea="${typea^^}" # uppercase for portability
typeb="${typeb^^}"
typead=`echo "ibase=16; $typea"|bc`
typebd=`echo "ibase=16; $typeb"|bc`
echo "Type A percent: $((typead * 10)) %"
echo "Type B percent: $((typebd * 10)) %"
Type A percent: 110 %
Type B percent: 110 %
Anyway, the topic of emmc wear if definitely worth digging for an app that writes data proportionally to activity of other apps that it doesn't control.
After killing the app and monitoring the WBYTES (shown as IO_W) in htop (WCHAR looks way higher on voice notify and other apps but I'm not really sure so it might get off the rails already here :( ).
There are writes even screen off in 11 minutes I get 46000 = 70 KiB/sec
Screen on without visible notification besides USB debug = 100 KiB/sec
unlocked = 96 KiB.
OMG even at the screen off rate that's 5.76 GiB per day and 2.05 TiB per year.
Without being plugged and without and adb shell open, the value should be lower due to power management.
Now when playing a video with the app Xtra (playing an archive of stream) Playback speed: 2
300 KiB/sec = 24 GiB per day. (when watching in 480p, that's even more than the actual data XD)
So 3 hours of watching per day raises the total to 1.1 TiB per year of those 3 hours per day. The additional contribution would likely be mostly the playback progress in the notification.
playback speed: 1
250 KiB/sec maybe or maybe not an impact. I suppose some app spam the notification proportionally to the speed.
Playing a video with NewPipe (a libre youtube player) Speed: 2
433 KiB/sec So 3 hours of watching per day raises the total to 1.59 TiB per year.
Imagine using it like a radio being on most of the day for music. (that's a actual common usage, right?)
Now listening to a podcast with AntennaPod. (screen stays on with app on foreground) Speed: 2.25
166 KiB/sec So 3 hours of watching per day raises the total to 624 GiB per year.
The lower value might be a sign that AntennaPod isn't overupdating the notification.
Now listening to music with vlc. (screen stays on with app on foreground) speed: 1
109 KiB/sec So 3 hours of watching per day raises the total to 409 GiB per year.
Nice value.
Now playing a video in Firefox on a Peertube instance. So I think it's just Firefox that is relevant there. Speed: 1
233 KiB/sec So 3 hours of watching per day raises the total to 876 GiB per year.
playback speed: 2
266 KiB/sec so likely no impact.
Another sample for idle with unlocked screen:
149 KiB/sec so there is quite a variation.
Not enough repetitions for individual scenarios. So there is that caveat on the data precision.
I could keep digging on my phone and elaborate more and more realistic scenarios to converge to isolating how much voice notify would be writing over a few years. But I'm past the point it's relevant alone with a given set of apps and on a given phone/ROM. Data from other people's phone is more relevant. And also the app counting itself how much it's writing. Instead of needing root to be able to cat /proc/$(pidof com.pilot51.voicenotify)/io . And root to get the amount written to emmc since boot:
grep 'mmcblk0 ' < /proc/diskstats | awk '{ print $3, ($10 * 512)/1024/1024, "M" }'
188968 M
184 GiB In 5 days 😱😱😱 is that even accurate???
I'll check at some point later after a reboot and letting it run. In the 5 days of uptime, I did again intensive tests with Xtra that spammed notifications.
By comparing the value before and after letting the phone idle unlocked during 20 min. It's supposed to be writing at 234 KiB/s globally on the emmc.
And at the same time via htop (WBYTES/IO_W) I get 223 KiB/s average. So on that sample of that scenario, emmc write is almost only voice notify. And /proc/diskstats looks accurate (😱). It matches htop showing almost no other write happening besides the periodical voice notify activity.
And that mostly confirms the IO_W column (WBYTES in setup) is relevant. WCHAR shows 28 times more. So no. Before that, I wasn't sure either of them was relevant. It could have shown less than actual writes due to not measuring the right thing. Or showing way too much due to some in-RAM virtual device. (I think that will always be a caveat for each app without a way to compare to physical emmc write) Or cache.
Bingo, WCHAR indeed include cache: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/Documentation/filesystems/proc.rst?id=HEAD#l1305
So it looks like these external measures of voice notify write are accurate. And so is total emmc write since boot.
184 GiB In 5 day 9 hr is 413 KiB/s. So it not that high compared to what I measured previously. Also my testing with Xtra shouldn't have caused that much increase vs regular use. In #166 I never saw more than 1.5 MiB/s directly in htop and the tests I didn't didn't make that last it long enough to pile dozens of GiB
New tool: https://source.android.com/docs/core/tests/debug/storaged
storaged --start &
storaged -u
This is great, the data is aggregated across app processes being killed. It shows foreground and background write (bg_wbytes/fg_wbytes). Remains to confirm if the data is persisted since last boot.
The format can be put in a text file and giving it a .csv extension makes libreoffice calc open it in a nice table.
Total wbytes: 158 GiB hmm, it's not that far off from the 184 GiB of /proc/diskstats. The docs says
the kernel keeps track of when a process exits so it doesn't miss I/O usage that occurs from the last storaged polling event.
So the difference can't be from there.
Maybe it can't capture some system stuff.
Like zygote64 has 110G of WBYTES in htop. It's way too much compared to /proc/diskstats so most of it might be a virtual device. Like /proc/diskstats shows zram0 with 176.265 G of write. So processes are missing from storaged and WBYTES might include zram0 or some other stuff.
I'll see if processes that have started since boot and are still there would have a similar value for WBYTES and in storaged.
com.android.providers.media.module is pretty almost a perfect match.
31 750 254 592 vs 31 750 164 480 bytes
Oh wow, I got the exact same value for an app in cat /proc/$(pidof MY.APP.PACKAGE)/io (the source of WBYTES value) and in storaged
So it's confirmed that storaged can persist WBYTES since boot.
This is amazing.
And WBYTES looks accurate for emmc write unless an app would be writing somewhere else.
So now the terrifying result for Voice Notify: 86 GiB. Compared to the 158 G total that storaged reports. And to the 184 GiB that /proc/diskstats reports.
That's an average of 193 KiB/s. Compared to the 1.5MiB/s peaks when I messed around with Xtra not more that long. So these 5 days of uptime shouldn't really be much impacted by this. The number of hours I listen videos or leave the phone plugged (no sleep so the CPU monitor and it's notification are still active) are likely to impact more how much Voice Notify ends up writing.
That's 15.9 GiB per day and over a year that's 5.6 TiB
It seems my phone should be using TLC NAND. (hopefully it's not QLC yet)
https://redlib.catsarch.com/r/hardware/comments/47gthx/emmcflash_readwrite_lifespan/
https://redlib.catsarch.com/r/Android/comments/ewume3/ufs_31_announced_with_improvements_in_speed_and/fg4xxqe/?context=3#fg4xxqe
And it can assumed for 1000 cycles
https://en.wikipedia.org/wiki/Flash_memory#Write_endurance
So for 64 GiB the upper bound is 62 TB
But this more like the upper bound.
https://source.android.com/docs/automotive/flash-wear
However, the system would stop functioning properly long before the flash memory completely wears out as the usable storage size decreases, and the eMMC may have an even shorter lifespan depending on the leveling techniques and the write patterns
... 🫤
The write patterns issue might be Write Amplification
https://en.wikipedia.org/wiki/Write_amplification
I struggle like hell to find a typical Write Amplification factor for an Android phone. Or any typical value...
But here:
https://www.usenix.org/system/files/atc24_slides-hwang.pdf
It shows values from 12 to 18. Maybe it's for really bad scenarios to demonstrate their new thing.
This is terrifying given the 62 TBW endurance vs the 5.6 TiB/per year that I can (not reliably) estimate from the past days of voice notify writes. So those TiB would need to be multiplied. Even if by 2, that's half of the (estimated) endurance in 3 years.
I can't find how to get the total data written on an eMMC of an Android phone. Only that percentage which I already have exceeded. And which is capping at 110%... So stuck on that front to actually know after how much TB/year an app can affect the life of a phone. Because the written patterns of voice notify might be great or not great. Since it's just one app. It's not like it's an average of typical phone usage across tons of apps.
More recent phones might support UFS:
https://xdaforums.com/t/discussion-check-flash-memory-ufs-version-rooting-needed.3600879/
And I think might be able to use SMART.
I could keep digging on my phone and elaborate more and more realistic scenarios to converge to isolating how much voice notify would be writing over a few years. But I'm past the point it's relevant alone
[... all the rest about other people trying to get that data. And adding in voice notify the logging the amount of write to the log itself]
So yeah, back to this ^^"
I would never have though circular debug logs could be something apps would ever need to watch how much they write to it.
Turns out these kind of things are legit concerns for IoT:
https://source.android.com/docs/automotive/flash-wear
the eMMC may have an even shorter lifespan depending on the leveling techniques and the write patterns used. In addition, this estimate does not consider the effects of misbehaved or malicious apps, which could disrupt Automotive systems by writing large blocks of junk data to flash memory without special permissions.
^^"
Also searching the web for "exceeded its maximum estimated device life time" will bring examples. Like on that home automation thing:
https://community.homey.app/t/howto-modding-investigating-homey-s-emmc-wear-estimation/101149/19
https://community.homey.app/t/howto-modding-investigating-homey-s-emmc-wear-estimation/101149/26
https://community.homey.app/t/howto-modding-investigating-homey-s-emmc-wear-estimation/101149/28