Jump to content


Photo

Slow response times and code 500 in emby-server logs

slow response code 500

  • Please log in to reply
8 replies to this topic

#1 fc7 OFFLINE  

fc7

    Advanced Member

  • Developers
  • 735 posts
  • Local time: 11:06 AM
  • LocationMadrid, Spain

Posted 09 December 2015 - 10:57 AM

I'm running the latest stable version of Emby on a CentOS 7 VM on Hyper-V 2012 R2 with the latest updates.

The VM is configured with 3GB of RAM and 4 vCPUs (the host is running a Intel® Xeon® CPU E3-1230 V2 @ 3.30GHz -4 cores + HT, 8 logical cores,-). The vNIC is configured using a NIC team on the host, so network connection is redudant and there is more bandwidth available.

I only have 2 concurrent users at most, from time to time but usually just me.

 

A couple of nights ago I was watching an episode of one of the shows using the Samsung TV app when suddenly playback stopped and the app went back to the episode information page reporting a "Network connection error".

This happened already a couple of times, always using the same app, but it was only the other night that I started to dig into it.

An important detail is that the Samsung app is not doing any transcoding on the server side, just direct streaming.

 

So far I couldn't find any network related issue (actually the network is very performant) or problems in the VM or Hypervisor itself.

What I did find that it's quite surprising is that in emby-server logs I can see more than a few responses taking a very long time, in the order of the couple of seconds, or even more.

While tailing emby-server log during normal playback I also checked the CPU, disk and memory usage. Since no transcoding is done, the CPUs are practically idle, less than 2% used. The disks (RAID 1+0 on a HP Smartarray P222 hardware raid card) are also barely used, but yet I keep seeing responses from time to time taking more than 2 o 3 seconds.

Anothe thing that called my attention is that many, many responses are returning a code 500 (internal server error?). But I don't see any affection on the user experience at all.

 

Please find attached a couple of server logs in case you want to take a look at them.

 

Right now I'm pretty much lost on why this responses return a 500 code, and even more surprised that sometimes the response time is so high, even when the VM is practically idling.

Attached Files



#2 fc7 OFFLINE  

fc7

    Advanced Member

  • Developers
  • 735 posts
  • Local time: 11:06 AM
  • LocationMadrid, Spain

Posted 09 December 2015 - 11:03 AM

Just as an example:

2015-12-07 22:59:53.8232 Info - HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-07 22:59:53.8410 Info - HttpServer: HTTP POST http://192.168.7.31:8096/emby/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (SmartHub; SMART-TV; U; Linux/SmartTV+2014; Maple2012) AppleWebKit/537.42+ (KHTML, like Gecko) SmartTV Safari/537.42+
2015-12-07 22:59:53.8535 Info - HttpServer: HTTP POST http://192.168.7.31:8096/emby/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (SmartHub; SMART-TV; U; Linux/SmartTV+2014; Maple2012) AppleWebKit/537.42+ (KHTML, like Gecko) SmartTV Safari/537.42+
2015-12-07 22:59:53.8535 Info - HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-07 22:59:53.8542 Info - HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-07 22:59:53.8551 Info - HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-07 22:59:53.8649 Info - HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-07 22:59:53.8779 Info - HttpServer: HTTP POST http://192.168.7.31:8096/emby/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (SmartHub; SMART-TV; U; Linux/SmartTV+2014; Maple2012) AppleWebKit/537.42+ (KHTML, like Gecko) SmartTV Safari/537.42+
2015-12-07 22:59:53.9347 Info - HttpServer: HTTP Response 500 to 192.168.7.53. Time: 75306ms (slow). http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-07 22:59:53.9352 Info - HttpServer: HTTP POST http://192.168.7.31:8096/emby/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (SmartHub; SMART-TV; U; Linux/SmartTV+2014; Maple2012) AppleWebKit/537.42+ (KHTML, like Gecko) SmartTV Safari/537.42+
2015-12-07 22:59:53.9881 Info - HttpServer: HTTP Response 204 to 192.168.7.53. Time: 110ms. http://192.168.7.31:8096/emby/Sessions/Playing/Progress
2015-12-07 22:59:54.0042 Info - HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-07 22:59:54.0125 Info - HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-07 22:59:54.0125 Info - HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-07 22:59:54.0232 Info - HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-07 22:59:54.0692 Info - HttpServer: HTTP Response 204 to 192.168.7.53. Time: 134ms. http://192.168.7.31:8096/emby/Sessions/Playing/Progress
2015-12-07 22:59:54.0784 Info - HttpServer: HTTP Response 204 to 192.168.7.53. Time: 237ms. http://192.168.7.31:8096/emby/Sessions/Playing/Progress
2015-12-07 22:59:54.1619 Info - HttpServer: HTTP Response 204 to 192.168.7.53. Time: 308ms. http://192.168.7.31:8096/emby/Sessions/Playing/Progress
2015-12-07 22:59:54.1788 Info - HttpServer: HTTP Response 500 to 192.168.7.53. Time: 166ms. http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-07 22:59:54.3027 Info - HttpServer: HTTP Response 500 to 192.168.7.53. Time: 438ms. http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-07 22:59:54.4369 Info - HttpServer: HTTP POST http://192.168.7.31:8096/emby/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (SmartHub; SMART-TV; U; Linux/SmartTV+2014; Maple2012) AppleWebKit/537.42+ (KHTML, like Gecko) SmartTV Safari/537.42+
2015-12-07 22:59:54.4839 Info - HttpServer: HTTP Response 500 to 192.168.7.53. Time: 661ms. http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-07 22:59:54.4842 Info - HttpServer: HTTP Response 500 to 192.168.7.53. Time: 630ms. http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-07 22:59:54.4842 Info - HttpServer: HTTP Response 500 to 192.168.7.53. Time: 662ms. http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-07 22:59:54.4842 Info - HttpServer: HTTP Response 500 to 192.168.7.53. Time: 630ms. http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-07 22:59:54.4842 Info - HttpServer: HTTP Response 500 to 192.168.7.53. Time: 629ms. http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-07 22:59:54.4842 Info - HttpServer: HTTP Response 500 to 192.168.7.53. Time: 661ms. http://192.168.7.31:8096/emby/Videos/5d21aa5e824df2bc591224d065c72b9e/Stream.mkv?static=true&MediaSourceId=5d21aa5e824df2bc591224d065c72b9e&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0

Look at this line:

 

2015-12-07 22:59:53.9347 Info - HttpServer: HTTP Response 500 to 192.168.7.53. Time: 75306ms (slow). http://192.168.7.31:...tartTimeTicks=0

 

This match the time (more or less) when the Samsumg app gave the network error and stopped playback (probably hit a timeout and abort playback?).

 

I'm not sure adding more RAM or vCPUs to the VM will help, but I'm open to any suggestions.

 

I'm must also admit that so far I'm not having any problems with playback (transcoding, music playback, etc). Only the network error message in the Samsung app and only from time to time. But after checking the logs and finding this I'm a little bit worried.


Edited by fc7, 09 December 2015 - 11:10 AM.


#3 fc7 OFFLINE  

fc7

    Advanced Member

  • Developers
  • 735 posts
  • Local time: 11:06 AM
  • LocationMadrid, Spain

Posted 10 December 2015 - 07:47 AM

I've been digging a little bit more on my own.

This morning I just tested by playing a music playlist, only my user accessing the server.

The response time are usually fine (3 ms) except with every song change:

2015-12-10 12:51:11.3113 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 3ms. http://192.168.7.31:8096/Sessions/Playing/Progress
2015-12-10 12:51:17.3040 Info HttpServer: HTTP POST http://192.168.7.31:8096/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:17.3072 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 3ms. http://192.168.7.31:8096/Sessions/Playing/Progress
2015-12-10 12:51:23.3092 Info HttpServer: HTTP POST http://192.168.7.31:8096/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:23.3123 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 3ms. http://192.168.7.31:8096/Sessions/Playing/Progress
2015-12-10 12:51:29.2987 Info HttpServer: HTTP POST http://192.168.7.31:8096/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:29.3022 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 3ms. http://192.168.7.31:8096/Sessions/Playing/Progress
2015-12-10 12:51:29.6777 Info HttpServer: HTTP POST http://192.168.7.31:8096/Sessions/Playing/Stopped. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:29.6823 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 4ms. http://192.168.7.31:8096/Sessions/Playing/Stopped
2015-12-10 12:51:29.7208 Info HttpServer: HTTP GET http://192.168.7.31:8096/web/nowplaying.html. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:29.7222 Info HttpServer: HTTP Response 304 to 213.30.8.162. Time: 1ms. http://192.168.7.31:8096/web/nowplaying.html
2015-12-10 12:51:29.7939 Info HttpServer: HTTP POST http://192.168.7.31:8096/Items/ac16ff353cee234a58f7553201039871/PlaybackInfo?UserId=668038acfab52e12250818ef610e97c5&StartTimeTicks=0. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:29.8166 Info HttpServer: HTTP Response 200 to 213.30.8.162. Time: 22ms. http://192.168.7.31:8096/Items/ac16ff353cee234a58f7553201039871/PlaybackInfo?UserId=668038acfab52e12250818ef610e97c5&StartTimeTicks=0
2015-12-10 12:51:29.8849 Info HttpServer: HTTP GET http://192.168.7.31:8096/Audio/ac16ff353cee234a58f7553201039871/stream.mp3?Static=true&mediaSourceId=ac16ff353cee234a58f7553201039871&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:30.1814 Info App: Emby.Kodi.SyncQueue:  Updating ItemId: '3c08d76a4fa0f886c29bfd4e67ee01dc' for UserId: '668038acfab52e12250818ef610e97c5' in table: 'UserInfoChangedQueue'
2015-12-10 12:51:30.1852 Info App: Emby.Kodi.SyncQueue:  Updating ItemId: '0d27cb2abccebfade7f464c084cf5f3e' for UserId: '668038acfab52e12250818ef610e97c5' in table: 'UserInfoChangedQueue'
2015-12-10 12:51:33.6150 Info HttpServer: HTTP POST http://192.168.7.31:8096/Sessions/Playing. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:33.6199 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 5ms. http://192.168.7.31:8096/Sessions/Playing
2015-12-10 12:51:34.1389 Info App: Emby.Kodi.SyncQueue:  Adding ItemId: 'ac16ff353cee234a58f7553201039871' for UserID: '668038acfab52e12250818ef610e97c5' to table: 'UserInfoChangedQueue'
2015-12-10 12:51:34.1612 Info App: Emby.Kodi.SyncQueue:  Updating ItemId: '0d27cb2abccebfade7f464c084cf5f3e' for UserId: '668038acfab52e12250818ef610e97c5' in table: 'UserInfoChangedQueue'
2015-12-10 12:51:34.6261 Info HttpServer: HTTP POST http://192.168.7.31:8096/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:34.6296 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 3ms. http://192.168.7.31:8096/Sessions/Playing/Progress
2015-12-10 12:51:35.5414 Info HttpServer: HTTP Response 206 to 213.30.8.162. Time: 5656ms (slow). http://192.168.7.31:8096/Audio/ac16ff353cee234a58f7553201039871/stream.mp3?Static=true&mediaSourceId=ac16ff353cee234a58f7553201039871&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1
2015-12-10 12:51:39.6507 Info HttpServer: HTTP POST http://192.168.7.31:8096/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:39.6539 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 3ms. http://192.168.7.31:8096/Sessions/Playing/Progress
2015-12-10 12:51:45.7067 Info HttpServer: HTTP POST http://192.168.7.31:8096/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:45.7098 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 3ms. http://192.168.7.31:8096/Sessions/Playing/Progress
2015-12-10 12:51:51.7041 Info HttpServer: HTTP POST http://192.168.7.31:8096/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:51.7071 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 3ms. http://192.168.7.31:8096/Sessions/Playing/Progress
2015-12-10 12:51:57.7049 Info HttpServer: HTTP POST http://192.168.7.31:8096/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0
2015-12-10 12:51:57.7078 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 3ms. http://192.168.7.31:8096/Sessions/Playing/Progress

Then I filtered just the slow responses:

2015-12-10 11:56:58.2555 Info HttpServer: HTTP Response 206 to 213.30.8.162. Time: 1308ms (slow). http://192.168.7.31:8096/Audio/4b7fd46de62ae0eaa7a22e3cdb4caa4d/stream.mp3?Static=true&mediaSourceId=4b7fd46de62ae0eaa7a22e3cdb4caa4d&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1
2015-12-10 11:59:09.6974 Info HttpServer: HTTP Response 206 to 213.30.8.162. Time: 2843ms (slow). http://192.168.7.31:8096/Audio/c5a0262627d43010d859dd9d2dbddadc/stream.mp3?Static=true&mediaSourceId=c5a0262627d43010d859dd9d2dbddadc&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1
2015-12-10 12:00:10.1948 Info HttpServer: HTTP Response 206 to 213.30.8.162. Time: 4085ms (slow). http://192.168.7.31:8096/Audio/4ac2ca6e9ac1db8933dab647f2cdb6c5/stream.mp3?Static=true&mediaSourceId=4ac2ca6e9ac1db8933dab647f2cdb6c5&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1
2015-12-10 12:05:43.1177 Info HttpServer: HTTP Response 206 to 213.30.8.162. Time: 8938ms (slow). http://192.168.7.31:8096/Audio/eb1b19dbdb05c1dfd17b2c5729b7ab9c/stream.mp3?Static=true&mediaSourceId=eb1b19dbdb05c1dfd17b2c5729b7ab9c&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1
2015-12-10 12:08:27.4172 Info HttpServer: HTTP Response 206 to 213.30.8.162. Time: 5814ms (slow). http://192.168.7.31:8096/Audio/b20bd21d799aafbe408648e4cbeed255/stream.mp3?Static=true&mediaSourceId=b20bd21d799aafbe408648e4cbeed255&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1
2015-12-10 12:11:34.5895 Info HttpServer: HTTP Response 206 to 213.30.8.162. Time: 5321ms (slow). http://192.168.7.31:8096/Audio/20a57e2f5619324565a7cce66f6e4856/stream.mp3?Static=true&mediaSourceId=20a57e2f5619324565a7cce66f6e4856&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1
2015-12-10 12:12:29.3741 Info HttpServer: HTTP Response 204 to 213.30.8.162. Time: 59729ms (slow). http://192.168.7.31:8096/Sessions/Playing
2015-12-10 12:16:03.7300 Info HttpServer: HTTP Response 206 to 213.30.8.162. Time: 5134ms (slow). http://192.168.7.31:8096/Audio/8d781aafd7e470e4257ad5faa871d201/stream.mp3?Static=true&mediaSourceId=8d781aafd7e470e4257ad5faa871d201&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1
2015-12-10 12:18:39.5125 Info HttpServer: HTTP Response 206 to 213.30.8.162. Time: 4756ms (slow). http://192.168.7.31:8096/Audio/8a1689d021a6b467715106b63b96182a/stream.mp3?Static=true&mediaSourceId=8a1689d021a6b467715106b63b96182a&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1
2015-12-10 12:22:52.3090 Info HttpServer: HTTP Response 206 to 213.30.8.162. Time: 7124ms (slow). http://192.168.7.31:8096/Audio/c58f2cc8176933055247917ab2b86c9f/stream.mp3?Static=true&mediaSourceId=c58f2cc8176933055247917ab2b86c9f&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1
2015-12-10 12:28:04.1986 Info HttpServer: HTTP Response 206 to 213.30.8.162. Time: 6593ms (slow). http://192.168.7.31:8096/Audio/ad3fa96a3cd32abd0ac7a4a39ac6db40/stream.mp3?Static=true&mediaSourceId=ad3fa96a3cd32abd0ac7a4a39ac6db40&deviceId=20323bf0243b18026f7df3b4f43debec1113c63b&api_key=2f426ef47022411faddbd1e9fe473fc1

I could determine that with every song change there is a significant increase in response times (from 3-6ms to 1000 times more). At the same time I was monitoring the server with top, and I can confirm that the server is basically idle all the time (around 1% CPU usage) and on a song change the CPU can go up to 2%-3% but that's all and still unsignificant.

My next suspect is I/O. All my media is on a separate file server VM, which Emby access using NFS. Both VMs are connected to the same virtual switch so there is no physical network involved. This file server is not busy at all, and the thoughput is excellent (> 100Mbytes/sec) but yet it's something I will try to check too from Emby process perspective.

 

@Luke: I have two questions. 1- Is this response time measure in the logs accurate and trust worthy? I just want to be sure I'm not chasing ghosts here and wasting my time. 2- Do you have any idea/suggestions on how can I profile Emby server process to try to understand where is the bottleneck? I found some information about mono and how to profile methods and so on but to be honest it's not my area of expertise.


Edited by fc7, 10 December 2015 - 07:57 AM.


#4 Luke OFFLINE  

Luke

    System Architect

  • Administrators
  • 142291 posts
  • Local time: 04:06 AM

Posted 10 December 2015 - 11:29 AM

that's normal. those responses don't end until the client stops streaming.



#5 fc7 OFFLINE  

fc7

    Advanced Member

  • Developers
  • 735 posts
  • Local time: 11:06 AM
  • LocationMadrid, Spain

Posted 10 December 2015 - 12:36 PM

that's normal. those responses don't end until the client stops streaming.

 

I don't want to waste your valuable time Luke, but would you mind briefly explaining how streaming works to the different clients? This will help me a lot to understand this.
 

Something like: "For audio streaming the full song is streamed to the client in one request. Video will be streamed in X secs chunks each chunk will be one http request." Don't you to waste too much time in this if it can't be briefly summarized.

 

I though that in every case, the client will get chunks of media to playback. If in this case, with audio, the client get the full media asset in one http request, then it makes perfect sense that a request for a song will take 13 seconds, since it's the time it takes the client to download the media file.


Edited by fc7, 10 December 2015 - 12:37 PM.


#6 Luke OFFLINE  

Luke

    System Architect

  • Administrators
  • 142291 posts
  • Local time: 04:06 AM

Posted 10 December 2015 - 12:40 PM

It's a static direct stream, so the http request is open and active throughout the entire time of playback.



#7 fc7 OFFLINE  

fc7

    Advanced Member

  • Developers
  • 735 posts
  • Local time: 11:06 AM
  • LocationMadrid, Spain

Posted 10 December 2015 - 01:24 PM

It's a static direct stream, so the http request is open and active throughout the entire time of playback.

 

I just took a network capture between a client (webclient) and the server and now I think I understand how it works. The client will download the complete song in one http request before starting playback.

The http request will remain open for the time it takes the client to download the media, that in most cases has nothing to do with the playback time but with the size of the media and the time it takes to transfer it to the client.

 

So for example the client jumps to the next song in a playlist and it will download the complete media and starts to playback. Then it's just updating the server on the playback progress every 5 seconds until it jumps to the next song.

If a song is 5 minutes long and 10MB in size, the http request will remain open for the time it takes the client to download the 10MB. If it takes 8 seconds it will remain open for 8 seconds, not the 5 minutes playback time of the song.

 

To be honest the response time reported in the logs can lead to confusion if you don't really know how the streaming works between the client and the server. :(

I guess I will have to do the same to understand how video streaming works.

 

@Luke: regarding the many requests with 500 code response that are present in the logs I shared. Is this also normal? Anything I need to be looking for? In my experience 500 code responses are never good at all.



#8 hvdbrand OFFLINE  

hvdbrand

    Member

  • Members
  • 10 posts
  • Local time: 11:06 AM

Posted 25 December 2015 - 07:30 AM

With great interest, I am reading this topic as I seem to have similar issues.

I may case I do a direct playback from my Emby server to a Samsung TV.

I see the following set of lines in my logs

2015-12-25 11:45:07.8926 Info HttpServer: HTTP GET http://192.168.1.78:8096/videos/642fb6b664ad491e65e9cc470bd916da/stream.mp4?Params=018026d07177d706cfe50a4f211ed2f2;test;642fb6b664ad491e65e9cc470bd916da;true;;;;;;;;;;;0;;;;;;;;;642fb6b664ad491e65e9cc470bd916da. UserAgent: 
2015-12-25 11:45:07.9232 Info HttpServer: HTTP Response 500 to 192.168.1.90. Time: 30ms. http://192.168.1.78:8096/videos/642fb6b664ad491e65e9cc470bd916da/stream.mp4?Params=018026d07177d706cfe50a4f211ed2f2;test;642fb6b664ad491e65e9cc470bd916da;true;;;;;;;;;;;0;;;;;;;;;642fb6b664ad491e65e9cc470bd916da

So every GET is answered by a 500 response.

Is this bad?

 

I noticed that while the time is low playback continues.

The playback abruptly stops after several HTTP response that are slow (even saw 40 s )

 

For me it is not yet clear if this time, is just the time it takes emby to send out a response or if this also includes sending the response over the network to the TV.

Could anyone clarify this for me?

 

Like fc7, I would also be interested in how response time issues could be debugged.



  • fc7 likes this

#9 fc7 OFFLINE  

fc7

    Advanced Member

  • Developers
  • 735 posts
  • Local time: 11:06 AM
  • LocationMadrid, Spain

Posted 25 December 2015 - 03:33 PM

I can confirm exactly the same behavior in the same scenario.

Latest Emby stable, SamsungTV Emby client 1.0.1. For many client requests the server response is 500 error code.

2015-12-25 13:56:01.7262 Info HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-25 13:56:01.9308 Info HttpServer: HTTP Response 500 to 192.168.7.47. Time: 204ms. http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-25 13:56:03.7248 Info HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-25 13:56:04.1408 Info HttpServer: HTTP Response 500 to 192.168.7.47. Time: 416ms. http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-25 13:56:04.2536 Info HttpServer: HTTP POST http://192.168.7.31:8096/emby/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (SmartHub; SMART-TV; U; Linux/SmartTV+2014; Maple2012) AppleWebKit/537.42+ (KHTML, like Gecko) SmartTV Safari/537.42+
2015-12-25 13:56:04.2589 Info HttpServer: HTTP Response 204 to 192.168.7.47. Time: 5ms. http://192.168.7.31:8096/emby/Sessions/Playing/Progress
2015-12-25 13:56:06.3264 Info HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-25 13:56:06.5326 Info HttpServer: HTTP Response 500 to 192.168.7.47. Time: 206ms. http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-25 13:56:07.1273 Info HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-25 13:56:07.3285 Info HttpServer: HTTP Response 500 to 192.168.7.47. Time: 201ms. http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-25 13:56:08.2931 Info HttpServer: HTTP POST http://192.168.7.31:8096/emby/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (SmartHub; SMART-TV; U; Linux/SmartTV+2014; Maple2012) AppleWebKit/537.42+ (KHTML, like Gecko) SmartTV Safari/537.42+
2015-12-25 13:56:08.2989 Info HttpServer: HTTP Response 204 to 192.168.7.47. Time: 6ms. http://192.168.7.31:8096/emby/Sessions/Playing/Progress
2015-12-25 13:56:08.5270 Info HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-25 13:56:08.9283 Info HttpServer: HTTP Response 500 to 192.168.7.47. Time: 401ms. http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-25 13:56:10.3272 Info HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-25 13:56:10.5320 Info HttpServer: HTTP Response 500 to 192.168.7.47. Time: 204ms. http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-25 13:56:11.7264 Info HttpServer: HTTP GET http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0. UserAgent: Lavf52.104.0
2015-12-25 13:56:12.1414 Info HttpServer: HTTP Response 500 to 192.168.7.47. Time: 415ms. http://192.168.7.31:8096/emby/Videos/35f44e0859984b9f085a1e92d876133a/Stream.mkv?static=true&MediaSourceId=35f44e0859984b9f085a1e92d876133a&api_key=2a9a4e1bc629411bad073399908237f6&DeviceId=ZPCM4M3HTU67Q&StartTimeTicks=0
2015-12-25 13:56:12.3036 Info HttpServer: HTTP POST http://192.168.7.31:8096/emby/Sessions/Playing/Progress. UserAgent: Mozilla/5.0 (SmartHub; SMART-TV; U; Linux/SmartTV+2014; Maple2012) AppleWebKit/537.42+ (KHTML, like Gecko) SmartTV Safari/537.42+
2015-12-25 13:56:12.3089 Info HttpServer: HTTP Response 204 to 192.168.7.47. Time: 5ms. http://192.168.7.31:8096/emby/Sessions/Playing/Progress

Note how every stream requests generate a 500 response but a progress update on the other hand gets a 204. Maybe @cmcg (Samsung app developer) may also want to have a look in case there is something to fix in the client request itself.

Funny thing is that video playback works fine from the sammy app, even with all these 500 responses.


Edited by fc7, 25 December 2015 - 03:43 PM.






Also tagged with one or more of these keywords: slow, response, code, 500

0 user(s) are reading this topic

0 members, 0 guests, 0 anonymous users