[tor-bugs] #33211 [Circumvention/Snowflake]: proxy-go sometimes gets into a 100+% CPU state

[Tor Bug Tracker & Wiki]

#33211: proxy-go sometimes gets into a 100+% CPU state
-------------------------------------+-----------------------------------
 Reporter:  dcf                      |          Owner:  (none)
     Type:  defect                   |         Status:  needs_information
 Priority:  Medium                   |      Milestone:
Component:  Circumvention/Snowflake  |        Version:
 Severity:  Normal                   |     Resolution:
 Keywords:                           |  Actual Points:
Parent ID:                           |         Points:
 Reviewer:                           |        Sponsor:
-------------------------------------+-----------------------------------

Comment (by cohosh):

 Starting to take a look at this. I haven't made it go into an infinite
 loop, but I have noticed that the proxy uses quite a bit of CPU,
 particularly if you have more than one client downloading files through
 it.

 The first thing that struck me was how much more expensive log messages
 are now that we're using safelog to perform regexes. The proxy-go
 instances are logging the byte count of every outgoing and incoming
 messaage [https://gitweb.torproject.org/pluggable-
 transports/snowflake.git/tree/proxy-go/snowflake.go#n94 here] and
 [https://gitweb.torproject.org/pluggable-transports/snowflake.git/tree
 /proxy-go/snowflake.go#n323 here]. Removing those shows that the remaining
 CPU time is spent in the pion library:

 {{{
 File: proxy-go
 Type: cpu
 Time: Feb 19, 2020 at 5:04pm (EST)
 Duration: 3.20mins, Total samples = 34.03s (17.73%)
 Entering interactive mode (type "help" for commands, "o" for options)
 (pprof) top --cum
 Showing nodes accounting for 7.20s, 21.16% of 34.03s total
 Dropped 423 nodes (cum <= 0.17s)
 Showing top 10 nodes out of 229
       flat  flat%   sum%        cum   cum%
      0.09s  0.26%  0.26%      9.87s 29.00%  runtime.systemstack
      0.05s  0.15%  0.41%      6.61s 19.42%
 github.com/pion/sctp.(*Association).writeLoop
         6s 17.63% 18.04%         6s 17.63%  runtime.futex
      0.03s 0.088% 18.13%      5.54s 16.28%
 github.com/pion/dtls.(*Conn).Write
      0.01s 0.029% 18.16%      5.30s 15.57%
 github.com/pion/dtls.(*Conn).flushPacketBuffer
      0.03s 0.088% 18.25%      5.24s 15.40%  runtime.mcall
      0.07s  0.21% 18.45%      5.01s 14.72%  runtime.schedule
      0.65s  1.91% 20.36%      4.81s 14.13%  runtime.mallocgc
      0.04s  0.12% 20.48%      4.35s 12.78%  runtime.park_m
      0.23s  0.68% 21.16%      4.25s 12.49%  runtime.findrunnable
 }}}

 Removing the log messages is a good start. Doing so makes it so that a
 single client downloading a large file over snowflake uses a maximum of
 about 43% CPU, whereas with the log messages, a single client would cause
 the proxy-go instance to use up to 60% CPU.

 I'll do a deeper dive into the pion code to see if there's something that
 can be optimized there.

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/33211#comment:5>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online