CPU usage is pretty high than previous v5.0.6

[xygwfxu]

when compared with previous 5.0.6, my xiaomi10 shows cpu is very high, almost 100% with full 8 core running.

when downgrade the v5.0.6, cpu becomes normal.

They are using same profile.

[madeye]

When you claim anything about CPU usage, make sure you post the battery usage info here.

adb shell dumpsys batterystats --charged com.github.shadowsocks

[xygwfxu]

from setting, it shows 28% battery used in minutes. and it's 0.7% while for 5.0.6。

before I filed this issue， I tried several time to make sure that issue is from this app. I am an Android app test QA(just to tell that I have some background of test Android.)

[madeye]

Make sure provide the batterystats info, you can dump the stats with this command:

adb shell dumpsys batterystats --charged com.github.shadowsocks

[notsure2]

I'm seeing this myself, this is idle phone sleeping:

Battery Stats here

@madeye

Realme 7 Pro Latest firmware Android 10

I will test with 5.1.4 and 5.0.6

[notsure2]

@madeye with 5.0.6 issue completely not present.
Without change any setting or profile upgrade to 5.1.4 issue appears, 5.1.6 same issues.

The issue is like this: When any app makes any network activity that needs to be proxied, libsslocal consumes very high CPU during the activity and even after the network traffic stops it keeps consuming high CPU.

Over time, one or two or three apps do network activity, result: libsslocal 100% CPU all cores for long time.

[notsure2]

If it helps, in my profile I have Redirect IPv6 enabled, I have Bypass Local Route, and I use 8.8.8.8 custom DNS. Also I have Apps VPN mode bypass, and I have a list of apps excluded from Shadowsocks.

[madeye]

It looks you enabled UDP fallback.

Can you disable UDP fallback and try again?

@notsure2

[notsure2]

@madeye The issue seems to be solved by disabling UDP fallback, however this is an important feature, I hope it can be fixed soon :-) Any explanation of the problem ? I am curious, was it packet looping or something like that ?

[madeye]

It could be a bug in previous versions of shadowsocks-rust.

I'll provide you a new APK to try out.

@notsure2

[notsure2]

@madeye I reported how timeout is completely broken in ss-rust, maybe it is wise to switch to ss-libev temporarily until ss-rust stabilizes. It's very obvious and clear that ss-rust is still in "development" phase unlike ss-libev which already passed the stabilization phase...

[madeye]

Please try this one:

https://drive.google.com/file/d/1eM16vBx3lQdoQAFiqBmcuF9aBYEcYksc/view?usp=drivesdk

[madeye]

We need to move on... 😊

With shadowsocks-rust, we can have better performance, DNS based ACL support, and many other important features for the future development.

You can still use 5.0.6 as a stable version.

So, just be patient...

[notsure2]

Hello,
Unfortunately, the test build improves the situation only slightly, it spikes only 1 core to 100% but it still acts the same. The bug is still there in shadowsocks-rust ...

The problem with using the old as stable is that the Play Store will auto update it against my will and I don't want to turn off auto updates on the whole phone. Is it possible perhaps to make a second "Legacy" build or "bug fix only" build with the 5.0.6 code base, or make an apk not connected to the play store so that it doesn't auto update ? At least for some months maybe until shadowsocks-rust is in a better shape. Maybe even release 2nd shadowsocks app in the store "legacy" version.

I expect still many more bugs in the near future because I can see the team is doing heavy refactoring and rebuilding which always introduces issues especially when there is no full exhaustive regression test suite.

Note: The UI in the test build is messed up a bit, the bottom part of the UI is rendered behind the navigation button bar like it's a full screen app...

[madeye]

@Mygod Can you reproduce this locally? I cannot reproduce it on any of my devices locally.

@notsure2 Please try these two APKs:

1. https://www.dropbox.com/s/c90g3ab0foorv16/shadowsocks-rust-1.8.23.apk
2. https://www.dropbox.com/s/sw2lbmj6ftl1o0a/shadowsocks-rust-1.9.0.apk

[Mygod]

[notsure2]

Hello @Mygod @madeye
I have investigated more deeply. I discovered that the UDP relay on my server is not working. When I fixed it, the high CPU usage issue disappeared, even the latest official 5.1.6 version.

shadowsocks-rust-1.9.0: UDP doesn't work at all, no UDP packets sent at all even with working server.
shadowsocks-rust-1.8.23: UDP relay works with different server without high CPU usage. But high CPU issue with the non-working server.

So there is a bug, but the bug is less severe, the high CPU usage occurs when the UDP relay connection is not working. So that's how to reproduce it.

Make a UDP relay on non-working server and then the broken behavior will happen.

ss-libev was simply not working, but it was correctly not working without making high CPU usage.

[madeye]

Make a UDP relay on non-working server and then the broken behavior will happen.

I cannot reproduce this locally. The only reason I can think of is that your system keep sending UDP packets to remote if there's no response.

IMO, it's a third-party bug of Xiaomi devices due to some backdoor service? Maybe switching to a pixel phone?

Also, please try this APK: https://www.dropbox.com/s/sw2lbmj6ftl1o0a/shadowsocks-rust-1.9.0-new.apk

[madeye]

@zonyitoo Do we have a limit for number of open socket of UDP relay in shadowsocks-rust?

It's possible we are out of sockets and get stuck if the system keep sending UDP packet from different local ports.

[notsure2]

@madeye i am happy to report with the 1.9.0-new, udp relay is working, and when I intentionally set it to a server with non-working UDP relay, it is not producing the high CPU usage anymore.

Thank you for fast fix :-) Hope to see new version soon.

[zonyitoo]

@zonyitoo Do we have a limit for number of open socket of UDP relay in shadowsocks-rust?

It's possible we are out of sockets and get stuck if the system keep sending UDP packet from different local ports.

Yes, set udp_max_associations to the limit you want.

In v1.9.0, this configuration will have a defult value 256. (not merged yet).

[madeye]

Cool! I guess it's because @zonyitoo limit the number to 256 now in v1.9.0.

Let me fix this in master branch as well.

[zonyitoo]

I haven't solve that in the master branch yet. https://github.com/shadowsocks/shadowsocks-rust/blob/a7c9f75d0767f5d8b8f2d23c6a8f70278429819f/shadowsocks/src/relay/udprelay/association.rs#L686-L690

So if your problem is solved, please make sure that you are compiling with the feature-separate-crates branch.

[madeye]

Sure, I will try that branch instead.

[madeye]

For now, we set udp_max_associations to 256 with shadowsocks-rust 1.8.23.

We will have a release soon for all the critical issues found recently.

[xygwfxu]

I just tested v5.1.7 on xiaomi 10 (android 11). Now with monitoring cpu usage, only one 2.84G core is 100% running, other 7 cores are in idle status. Not sure how I can help on this for more.

My profile don't have "UDP relay" option, my profile is simple, just host, port, encryption, china-bypass, 4 options.

Since we cannot stop xiaomi sending stupid UDP packets(if you were rigth), is that impossible to fix at all?

[madeye]

@xygwfxu Have you tried this APK? https://www.dropbox.com/s/sw2lbmj6ftl1o0a/shadowsocks-rust-1.9.0-new.apk

[xygwfxu]

@madeye does v5.1.7 not contain fix from shadowsocks-rust-1.9.0-new.apk?
Let me try this one and update you soon.

[xygwfxu]

@madeye wow, what magic you made, that's too awesome!!!
I cannot reproduce cpu high usage on the apk you sent(1.9.0) .

Appreciated your great helps again.

[madeye]

@zonyitoo Anything changed in UDP relay in 1.9.0, except udp_max_associations?

[zonyitoo]

Everything changes in v1.9.0. :P .. which is completely refactored.

[zonyitoo]

Now with monitoring cpu usage, only one 2.84G core is 100% running, other 7 cores are in idle status.

So there must be a infinite loop, did you see anything related via logging output?

[madeye]

The 1.9.0 apk I provided is still using the master branch.

So I think there is some key change to UDP association on master branch recently, which fixed the issue here.

[xygwfxu]

@zonyitoo The log is adb logcat right?

[zonyitoo]

I have no idea. Where did sslocal's output log store? @madeye

[xygwfxu]

No luck on logcat, no logfile for libsslocal.so according to /proc/pid/fd (there are about 40 socket opened).
19582 u0_a237 20 0 66M 42M 3.2M R 90.9 1.1 5:21.68 libsslocal.so libsslocal.so

[xygwfxu]

I use strace to attach this proc, and see same line below but copy to few thousands in second:

[7fd4cf9c80] 21013: recvfrom (33 socket:[7135356],(0x7eaef7b880),65536,0x0,0x0) = -11 (Try again)
[7fd4cf9c80] 21013: recvfrom (24 socket:[7131949],(0x7eae60db80),65536,0x0,0x0) = -11 (Try again)

[zonyitoo]

[7fd2276720] 19582: recvfrom (25 socket:[7091543],(0x787c3e9140),65536,0x0,0x0) = -11 (Try again)

Could you verify that those thousands of recvfrom is for the same fd?

[xygwfxu]

Just tried again, two sockets in looply.

[zonyitoo]

What is that -11 (Try again) means? EAGAIN?

[xygwfxu]

should be： #define EAGAIN 11 /* Try again */

[zonyitoo]

I think that must be a bug in tokio. The recvfrom call should only be used for UDP sockets in this project. If sockets returned EAGAIN, tokio should register readiness event and yield the current coroutine.

[madeye]

It's quite weird that recvfrom for UDP socket would get EAGAIN.

[zonyitoo]

@xygwfxu Have you seen any ERROR outputs in stderr/stdout?

[xygwfxu]

@zonyitoo It's an android phone, I not sure how to get stderr/stdout from sslocal anyway.

[zonyitoo]

Have you redirect sslocal's output to files? @madeye

[madeye]

To get the log from sslocal, just type adb logcat -s libsslocal.

[xygwfxu]

Look like I see some error:
12-18 10:51:43.825 17193 17647 E libsslocal: 2020-12-18T10:51:43.824524481+08:00 ERROR TCP socks5 client exited with error: CONNECT 15.xx.xx.82:33445 failed with error "Connection timed out (os error 110)"
12-18 10:51:45.489 17193 17647 E libsslocal: 2020-12-18T10:51:45.489345053+08:00 ERROR TCP socks5 client exited with error: early eof
12-18 10:51:45.491 17193 17647 E libsslocal: 2020-12-18T10:51:45.490943282+08:00 ERROR TCP socks5 client exited with error: early eof
12-18 10:52:53.573 17193 17647 E libsslocal: 2020-12-18T10:52:53.560304090+08:00 ERROR UDP association recv 127.0.0.1:42768 <- .., error: Connection refused (os error 111)

[zonyitoo]

12-18 10:52:53.573 17193 17647 E libsslocal: 2020-12-18T10:52:53.560304090+08:00 ERROR UDP association recv 127.0.0.1:42768 <- .., error: Connection refused (os error 111)

That's strange. It seems that the endpoint returns an ICMP failure.

[xygwfxu]

Verified at v5.1.8, cpu high usage is not able to reproduce.