ruby-mpd
ruby-mpd copied to clipboard
archseer
Adding songs to the queue is slow
On my live music server:
@mpd.add( song ) # takes about 40ms
`mpc add "#{song.file}"` # takes about 5ms
This may seem trivial, but when dynamically generating the queue with 100 songs this is the difference between waiting 4 seconds versus half a second.
I wonder if this is the @mutex.synchronize slowing me down; I'll be looking at ways to speed up the batch adding of many songs.
I've fixed this in my fork by implementing command_list. I can now add songs at about 3-4ms per song in batch mode.
I'll try to find time to create a pull request for command_list.
Hmm, would you mind getting me a profile of that method call? http://tmm1.net/ruby21-profiling/
Would be good to see where we're spending most of the execution time.
Stackprof did not work for me: https://github.com/tmm1/stackprof/issues/63
So, instead I manually profiled the send_command method and its three child methods, convert_command, handle_server_response, and parse_response. I did this by wrapping each method in:
t1 = Time.now
# code from the method
last_statement.tap{ $prof[:methodname] << (Time.now-t1) }
and creating a global $prof hash with pre-allocated arrays. The full results can be seen here:
https://docs.google.com/spreadsheets/d/1JNUweNAmfEEqbj7wqTXB6A3hxgYwBlAhw1rmuHosodA/edit?usp=sharing
The summary is:
function_call avg ms median ms
----------------------------------------------
send_command 45.863 40.006
convert_command 0.047 0.044
handle_server_response 45.777 39.907
parse_response 0.004 0.004
In other words, ~all (99.8%) of the time is spent waiting on gets from the socket. This profiling code was run in a live environment, where (as normally happens) another process is polling the MPD server status every 500ms.
Using a different profiling mode with stackprof I got results from it. Not sure how much to trust them, though, since the results are so different for intervals of 1000µs (1ms), 500µs, 100µs, 50µs, and 5µs:
==================================
Mode: wall(1000)
Samples: 131 (97.13% miss rate)
GC: 1 (0.76%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
107 (81.7%) 107 (81.7%) MPD#handle_server_response
12 (9.2%) 12 (9.2%) MPD::Parser#quotable_param
127 (96.9%) 3 (2.3%) block in MPD#send_command
15 (11.5%) 3 (2.3%) block in MPD::Parser#convert_command
2 (1.5%) 2 (1.5%) MPD#socket
16 (12.2%) 1 (0.8%) MPD::Parser#convert_command
130 (99.2%) 1 (0.8%) MPD::Plugins::Queue#add
1 (0.8%) 1 (0.8%) Set#include?
130 (99.2%) 0 (0.0%) block in RubyLex#each_top_level_statement
130 (99.2%) 0 (0.0%) block (2 levels) in IRB::Irb#eval_input
==================================
Mode: wall(500)
Samples: 120 (98.68% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
108 (90.0%) 108 (90.0%) MPD#handle_server_response
6 (5.0%) 6 (5.0%) MPD::Parser#quotable_param
120 (100.0%) 2 (1.7%) block in MPD#send_command
8 (6.7%) 2 (1.7%) MPD::Parser#convert_command
1 (0.8%) 1 (0.8%) MPD#socket
1 (0.8%) 1 (0.8%) MPD::Parser#parse_response
120 (100.0%) 0 (0.0%) Object#irb_binding
120 (100.0%) 0 (0.0%) IRB::WorkSpace#evaluate
120 (100.0%) 0 (0.0%) IRB::Context#evaluate
120 (100.0%) 0 (0.0%) block (2 levels) in IRB::Irb#eval_input
==================================
Mode: wall(100)
Samples: 193 (99.58% miss rate)
GC: 1 (0.52%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
113 (58.5%) 113 (58.5%) MPD#handle_server_response
37 (19.2%) 37 (19.2%) MPD::Parser#quotable_param
54 (28.0%) 12 (6.2%) MPD::Parser#convert_command
185 (95.9%) 12 (6.2%) block in MPD#send_command
42 (21.8%) 5 (2.6%) block in MPD::Parser#convert_command
5 (2.6%) 5 (2.6%) MPD#socket
192 (99.5%) 4 (2.1%) MPD::Plugins::Queue#add
2 (1.0%) 2 (1.0%) Set#include?
4 (2.1%) 2 (1.0%) MPD::Parser#parse_response
192 (99.5%) 0 (0.0%) #<Module:0x000000021b7298>.start
==================================
Mode: wall(50)
Samples: 306 (99.66% miss rate)
GC: 4 (1.31%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
128 (41.8%) 125 (40.8%) MPD#handle_server_response
72 (23.5%) 72 (23.5%) MPD::Parser#quotable_param
287 (93.8%) 46 (15.0%) block in MPD#send_command
103 (33.7%) 19 (6.2%) MPD::Parser#convert_command
19 (6.2%) 19 (6.2%) MPD#socket
84 (27.5%) 12 (3.9%) block in MPD::Parser#convert_command
3 (1.0%) 3 (1.0%) Set#include?
6 (2.0%) 3 (1.0%) MPD::Parser#parse_response
302 (98.7%) 3 (1.0%) MPD::Plugins::Queue#add
302 (98.7%) 0 (0.0%) block in RubyLex#each_top_level_statement
==================================
Mode: wall(5)
Samples: 28041 (97.16% miss rate)
GC: 59 (0.21%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
9020 (32.2%) 9020 (32.2%) MPD#socket
8348 (29.8%) 8271 (29.5%) MPD#handle_server_response
3354 (12.0%) 3354 (12.0%) MPD::Parser#quotable_param
2329 (8.3%) 2329 (8.3%) Set#include?
4984 (17.8%) 1630 (5.8%) block in MPD::Parser#convert_command
1453 (5.2%) 1453 (5.2%) MPD#connected?
3089 (11.0%) 760 (2.7%) MPD::Parser#parse_response
21574 (76.9%) 472 (1.7%) block in MPD#send_command
5387 (19.2%) 403 (1.4%) MPD::Parser#convert_command
27975 (99.8%) 120 (0.4%) MPD::Plugins::Queue#add
Following up from discussion over on the stackprof issue: the "97% miss rate" indicates that the profiler is not able to see most of the code, because it's being blocked by socket.gets. So, the stackprof results are not great in this case.
The only thing it did point out was that handle_server_response is calling MPD#socket for each line of response. Though this is just an ||=, it does have the overhead of a method call. In b01adf49 I've patched the method to cache the socket at the beginning of the call.
I think this is most likely caused on the server side then, since we're waiting for a response to each command. I think what MPC does is completely ignore the response from the server
You could also try using a UNIX socket, I think those should be faster than TCP for local connections