Jump to content

Powershell Script to show # of SLOW entries per Server Log

MSattler

By MSattler
in Tools and Utilities

 Share

Recommended Posts

ebr Emby Team

ebr   14903

Posted
Posted

@@Luke ,

 

So when we see SLOW entries in the log, is this purely a reflection of the server's ability to handle get requests from the client?  Or could this be caused by a slow client as well?

 

Thanks!

 

The client should not be a factor in that particular timing.

  • Like 1
Link to comment
Share on other sites
MSattler

MSattler   387

Posted
  • Author
Posted

The client should not be a factor in that particular timing.

 

It's interesting looking at these slow entries because for instance in the last 2 hours no one has played anything but I have 3 more slow entries.  Nothing but Emby runs on this i7-6700 with 24GB of ram.

 

Interestingly enough these 3 slow entries were from a.... slower persay client.  My laptop at the office has a ssh-tunnel into a linux box at my house, and I proxy firefox through that linux box, to load Emby.  I commonly see slow errors in this fashion, and the 3 slow entries when nothing was going on went through that box.  It makes me think that a slow client perhaps can cause some of these slow measurements.

 

How are you measuring all this?  Is it from the time a client sends a request until the server has sent it's reply?  

  • Like 1
Link to comment
Share on other sites
MSattler

MSattler   387

Posted
  • Author
Posted

@@Luke

 

Noticed this today,  one of these slow errors is 17 minutes, which is how far I was into playback, when I x'd out of firefox.  

 

2016-05-27 16:49:08.1141 Info HttpServer: HTTP Response 500 to 192.168.1.239. Time: 1025302ms (slow). http://192.168.1.125:8096/emby/videos/41211691194ce402a90616f50f8b4916/stream.mp

 

What is it trying to do for 17 minutes?

 

 

2016-05-27 16:32:02.7339 Info App: Bitrate exceeds DirectPlay limit
2016-05-27 16:32:02.7339 Info App: Profile: Unknown Profile, Path: \\tower\TV-Series\Blindspot\Season 1\Blindspot.S01E23.mkv, isEligibleForDirectPlay: True, isEligibleForDirectStream: False
2016-05-27 16:32:02.7339 Info App: Profile: Unknown Profile, No direct play profiles found for Path: \\tower\TV-Series\Blindspot\Season 1\Blindspot.S01E23.mkv
2016-05-27 16:32:02.7339 Info App: RemoteClientBitrateLimit: 20000000, RemoteIp: 192.168.1.239, IsInLocalNetwork: True
2016-05-27 16:32:02.7339 Info App: Bitrate exceeds DirectPlay limit
2016-05-27 16:32:02.7339 Info App: Profile: Unknown Profile, Path: \\tower\TV-Series\Blindspot\Season 1\Blindspot.S01E23.mkv, isEligibleForDirectPlay: True, isEligibleForDirectStream: False
2016-05-27 16:32:02.7339 Info App: Profile: Unknown Profile, No direct play profiles found for Path: \\tower\TV-Series\Blindspot\Season 1\Blindspot.S01E23.mkv
2016-05-27 16:32:02.7339 Info App: RemoteClientBitrateLimit: 20000000, RemoteIp: 192.168.1.239, IsInLocalNetwork: True
2016-05-27 16:32:02.7339 Info App: Bitrate exceeds DirectPlay limit
2016-05-27 16:32:02.7339 Info App: Profile: Unknown Profile, Path: \\tower\TV-Series\Blindspot\Season 1\Blindspot.S01E23.mkv, isEligibleForDirectPlay: True, isEligibleForDirectStream: False
2016-05-27 16:32:02.7339 Info App: Profile: Unknown Profile, No direct play profiles found for Path: \\tower\TV-Series\Blindspot\Season 1\Blindspot.S01E23.mkv
2016-05-27 16:32:02.8121 Info App: B:\Users\Administrator\AppData\Roaming\Emby-Server\ffmpeg\20160410\ffmpeg.exe -fflags +genpts -i file:"\\tower\TV-Series\Blindspot\Season 1\Blindspot.S01E23.mkv" -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_qsv -force_key_frames expr:gte(t,n_forced*5) -vf "scale=trunc(min(max(iw\,ih*dar)\,720)/2)*2:trunc(ow/dar/2)*2" -preset 7 -look_ahead 0 -b:v 872001 -maxrate 872001 -bufsize 1744002 -vsync -1 -profile:v high -level 4.1 -map_metadata -1 -threads 0 -codec:a:0 aac -strict experimental -ac 6 -ab 128000 -af "aresample=async=1" -f mp4 -movflags frag_keyframe+empty_moov -y "B:\Users\Administrator\AppData\Roaming\Emby-Server\transcoding-temp\transcoding-temp\6c1c5f280b62a647c2965f642242e86f.mp4"
2016-05-27 16:32:07.4685 Info HttpServer: HTTP POST http://192.168.1.125:8096/emby/Sessions/Playing. UserAgent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:46.0) Gecko/20100101 Firefox/46.0
2016-05-27 16:32:07.4685 Info HttpServer: HTTP Response 204 to 192.168.1.239. Time: 0ms. http://192.168.1.125:8096/emby/Sessions/Playing
2016-05-27 16:32:40.6551 Info HttpServer: HTTP GET https://emby.marcusrocks.com:8920/emby/Shows/NextUp?EnableImageTypes=&Limit=1&UserId=78e543ce7631423db0fa8ac03152ee78&Fields=PrimaryImageAspectRatio&format=json. UserAgent: Dalvik/2.1.0 (Linux; U; Android 6.0; SHIELD Android TV Build/MRA58K)
2016-05-27 16:32:40.6864 Info HttpServer: HTTP GET https://emby.marcusrocks.com:8920/emby/Users/78e543ce7631423db0fa8ac03152ee78/Items/Latest?Limit=1&IsPlayed=false&IncludeItemTypes=Episode&Fields=PrimaryImageAspectRatio&GroupItems=false&format=json. UserAgent: Dalvik/2.1.0 (Linux; U; Android 6.0; SHIELD Android TV Build/MRA58K)
2016-05-27 16:32:41.0799 Info HttpServer: HTTP GET https://emby.marcusrocks.com:8920/emby/Users/78e543ce7631423db0fa8ac03152ee78/Items/Latest?Limit=1&IsPlayed=false&IncludeItemTypes=Movie&Fields=PrimaryImageAspectRatio&GroupItems=false&format=json. UserAgent: Dalvik/2.1.0 (Linux; U; Android 6.0; SHIELD Android TV Build/MRA58K)
2016-05-27 16:32:41.1501 Info HttpServer: HTTP GET https://emby.marcusrocks.com:8920/emby/Items/c1d078aac841aab8d2d78efe45ad96e9/Similar?Limit=10&UserId=78e543ce7631423db0fa8ac03152ee78&Fields=PrimaryImageAspectRatio&format=json. UserAgent: Dalvik/2.1.0 (Linux; U; Android 6.0; SHIELD Android TV Build/MRA58K)
2016-05-27 16:32:41.3532 Info HttpServer: HTTP GET https://emby.marcusrocks.com:8920/emby/Items/3231d1bd0fe843bee00ae6a4088a463b/Similar?Limit=10&UserId=78e543ce7631423db0fa8ac03152ee78&Fields=PrimaryImageAspectRatio&format=json. UserAgent: Dalvik/2.1.0 (Linux; U; Android 6.0; SHIELD Android TV Build/MRA58K)
2016-05-27 16:33:27.3687 Error NotFoundHttpHandler: [::ffff:192.168.1.125]:8096 Request not found: /web/index.html
2016-05-27 16:33:27.4629 Error NotFoundHttpHandler: [::ffff:192.168.1.125]:8920 Request not found: /web/index.html
2016-05-27 16:34:31.0338 Info App: Udp message sent to 192.168.1.56:60383
2016-05-27 16:34:31.0338 Info App: Udp message sent to 192.168.1.56:60383
2016-05-27 16:34:32.0807 Info HttpServer: HTTP GET http://192.168.1.125:8096/emby/system/info/public?format=json. UserAgent: Dalvik/2.1.0 (Linux; U; Android 6.0; SHIELD Android TV Build/MRA58K)
2016-05-27 16:34:32.0807 Info HttpServer: HTTP Response 200 to 192.168.1.56. Time: 0ms. http://192.168.1.125:8096/emby/system/info/public?format=json
2016-05-27 16:34:32.0964 Info HttpServer: HTTP GET http://192.168.1.125:8096/emby/system/info?format=json. UserAgent: Dalvik/2.1.0 (Linux; U; Android 6.0; SHIELD Android TV Build/MRA58K)
2016-05-27 16:34:32.1120 Info HttpServer: HTTP Response 200 to 192.168.1.56. Time: 16ms. http://192.168.1.125:8096/emby/system/info?format=json
2016-05-27 16:34:32.1433 Info HttpServer: HTTP GET http://192.168.1.125:8096/mediabrowser/users/80678f1cca3e43a9871d783f0ed189ee?format=json. UserAgent: Dalvik/2.1.0 (Linux; U; Android 6.0; SHIELD Android TV Build/MRA58K)
2016-05-27 16:34:32.1433 Info HttpServer: HTTP Response 200 to 192.168.1.56. Time: 0ms. http://192.168.1.125:8096/mediabrowser/users/80678f1cca3e43a9871d783f0ed189ee?format=json
2016-05-27 16:34:32.1745 Info HttpServer: HTTP POST http://192.168.1.125:8096/emby/Sync/Data?format=json. UserAgent: Dalvik/2.1.0 (Linux; U; Android 6.0; SHIELD Android TV Build/MRA58K)
2016-05-27 16:34:32.1745 Info HttpServer: HTTP Response 200 to 192.168.1.56. Time: 0ms. http://192.168.1.125:8096/emby/Sync/Data?format=json
2016-05-27 16:34:32.1901 Info HttpServer: HTTP GET http://192.168.1.125:8096/emby/Sync/Items/Ready?TargetId=a77ecee533423984TIAMAT&format=json. UserAgent: Dalvik/2.1.0 (Linux; U; Android 6.0; SHIELD Android TV Build/MRA58K)
2016-05-27 16:34:32.1901 Info HttpServer: HTTP Response 200 to 192.168.1.56. Time: 0ms. http://192.168.1.125:8096/emby/Sync/Items/Ready?TargetId=a77ecee533423984TIAMAT&format=json
2016-05-27 16:34:32.2683 Info HttpServer: HTTP POST http://192.168.1.125:8096/emby/Sync/Data?format=json. UserAgent: Dalvik/2.1.0 (Linux; U; Android 6.0; SHIELD Android TV Build/MRA58K)
2016-05-27 16:34:32.2683 Info HttpServer: HTTP Response 200 to 192.168.1.56. Time: 0ms. http://192.168.1.125:8096/emby/Sync/Data?format=json
2016-05-27 16:38:47.4486 Error NotFoundHttpHandler: [::ffff:192.168.1.125]:8096 Request not found: /web/index.html
2016-05-27 16:38:47.6986 Error NotFoundHttpHandler: [::ffff:192.168.1.125]:8920 Request not found: /web/index.html
2016-05-27 16:38:48.7769 Error NotFoundHttpHandler: [::ffff:192.168.1.125]:8096 Request not found: /web/index.html
2016-05-27 16:38:48.8706 Error NotFoundHttpHandler: [::ffff:192.168.1.125]:8920 Request not found: /web/index.html
2016-05-27 16:38:49.6000 Info App: FFMpeg exited with code 0
2016-05-27 16:44:08.8899 Error NotFoundHttpHandler: [::ffff:192.168.1.125]:8096 Request not found: /web/index.html
2016-05-27 16:44:09.1400 Error NotFoundHttpHandler: [::ffff:192.168.1.125]:8920 Request not found: /web/index.html
2016-05-27 16:45:59.5957 Error NotFoundHttpHandler: [::ffff:192.168.1.125]:8096 Request not found: /web/index.html
2016-05-27 16:45:59.6582 Error NotFoundHttpHandler: [::ffff:192.168.1.125]:8920 Request not found: /web/index.html
2016-05-27 16:49:08.1141 Error App: Error streaming media. The client has most likely disconnected or transcoding has failed.
*** Error Report ***
Version: 3.1.0.0
Command line: B:\Users\Administrator\AppData\Roaming\Emby-Server\system\MediaBrowser.ServerApplication.exe -service
Operating system: Microsoft Windows NT 6.2.9200.0
Processor count: 8
64-Bit OS: True
64-Bit Process: True
Program data path: B:\Users\Administrator\AppData\Roaming\Emby-Server
Application Path: B:\Users\Administrator\AppData\Roaming\Emby-Server\system\MediaBrowser.ServerApplication.exe
One or more errors occurred.
System.AggregateException
  at System.Threading.Tasks.Task.WaitAll(Task[] tasks, Int32 millisecondsTimeout, CancellationToken cancellationToken)
  at MediaBrowser.Api.Playback.Progressive.ProgressiveStreamWriter.WriteToInternal(Stream responseStream)
InnerException: System.IO.IOException
Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host.
  at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
  at SocketHttpListener.Net.ResponseStream.InternalWrite(Byte[] buffer, Int32 offset, Int32 count)
  at SocketHttpListener.Net.ResponseStream.Write(Byte[] buffer, Int32 offset, Int32 count)
  at MediaBrowser.Api.Playback.Progressive.ProgressiveFileCopier.CopyToInternal(Stream source, Stream destination, Int32 bufferSize)
  at MediaBrowser.Api.Playback.Progressive.ProgressiveFileCopier.<StreamFile>d__0.MoveNext()
InnerException: System.Net.Sockets.SocketException
An existing connection was forcibly closed by the remote host
  at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
  at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
 
2016-05-27 16:49:08.1141 Error HttpServer: Error in HttpListenerResponseWrapper: Unable to write data to the transport connection: An established connection was aborted by the software in your host machine.
*** Error Report ***
Version: 3.1.0.0
Command line: B:\Users\Administrator\AppData\Roaming\Emby-Server\system\MediaBrowser.ServerApplication.exe -service
Operating system: Microsoft Windows NT 6.2.9200.0
Processor count: 8
64-Bit OS: True
64-Bit Process: True
Program data path: B:\Users\Administrator\AppData\Roaming\Emby-Server
Application Path: B:\Users\Administrator\AppData\Roaming\Emby-Server\system\MediaBrowser.ServerApplication.exe
Unable to write data to the transport connection: An established connection was aborted by the software in your host machine.
System.IO.IOException
  at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
  at SocketHttpListener.Net.ResponseStream.InternalWrite(Byte[] buffer, Int32 offset, Int32 count)
  at SocketHttpListener.Net.ResponseStream.Close()
  at MediaBrowser.Server.Implementations.HttpServer.SocketSharp.Extensions.CloseOutputStream(HttpListenerResponse response, ILogger logger)
InnerException: System.Net.Sockets.SocketException
An established connection was aborted by the software in your host machine
  at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
  at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
 
2016-05-27 16:49:08.1141 Error HttpAsyncTaskHandler: Error occured while Processing Request: Unable to write data to the transport connection: An established connection was aborted by the software in your host machine.
*** Error Report ***
Version: 3.1.0.0
Command line: B:\Users\Administrator\AppData\Roaming\Emby-Server\system\MediaBrowser.ServerApplication.exe -service
Operating system: Microsoft Windows NT 6.2.9200.0
Processor count: 8
64-Bit OS: True
64-Bit Process: True
Program data path: B:\Users\Administrator\AppData\Roaming\Emby-Server
Application Path: B:\Users\Administrator\AppData\Roaming\Emby-Server\system\MediaBrowser.ServerApplication.exe
Unable to write data to the transport connection: An established connection was aborted by the software in your host machine.
System.IO.IOException
  at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
  at SocketHttpListener.Net.ResponseStream.InternalWrite(Byte[] buffer, Int32 offset, Int32 count)
  at SocketHttpListener.Net.ResponseStream.Write(Byte[] buffer, Int32 offset, Int32 count)
  at ServiceStack.Formats.HtmlFormat.SerializeToStream(IRequest request, Object response, IResponse httpRes)
  at ServiceStack.HttpResponseExtensionsInternal.WriteErrorToResponse(IResponse httpRes, IRequest httpReq, String contentType, String operationName, String errorMessage, Exception ex, Int32 statusCode)
  at ServiceStack.ServiceStackHost.OnUncaughtException(IRequest httpReq, IResponse httpRes, String operationName, Exception ex)
  at ServiceStack.HostContext.RaiseUncaughtException(IRequest httpReq, IResponse httpRes, String operationName, Exception ex)
  at ServiceStack.HttpResponseExtensionsInternal.WriteToResponse(IResponse response, Object result, ResponseSerializerDelegate defaultAction, IRequest request, Byte[] bodyPrefix, Byte[] bodySuffix)
  at ServiceStack.HttpResponseExtensionsInternal.WriteToResponse(IResponse httpRes, IRequest httpReq, Object result, Byte[] bodyPrefix, Byte[] bodySuffix)
  at ServiceStack.HttpResponseExtensionsInternal.WriteToResponse(IResponse httpRes, IRequest httpReq, Object result)
  at ServiceStack.Host.Handlers.ServiceStackHandlerBase.HandleResponse(Object response, Func`2 callback, Func`2 errorCallback)
InnerException: System.Net.Sockets.SocketException
An established connection was aborted by the software in your host machine
  at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
  at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
 
2016-05-27 16:49:08.3329 Info HttpServer: HTTP POST http://192.168.1.125:8096/emby/Sessions/Playing/Stopped. UserAgent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:46.0) Gecko/20100101 Firefox/46.0
2016-05-27 16:49:08.3483 Info App: Deleting partial stream file(s) B:\Users\Administrator\AppData\Roaming\Emby-Server\transcoding-temp\transcoding-temp\6c1c5f280b62a647c2965f642242e86f.mp4
2016-05-27 16:49:08.3483 Info HttpServer: HTTP Response 204 to 192.168.1.239. Time: 15ms. http://192.168.1.125:8096/emby/Sessions/Playing/Stopped
Link to comment
Share on other sites
Luke Emby Team

Luke   37008

Posted
Posted

the http server component generically adds that slow marker for all requests that stay open for longer than 1000ms, but sometimes there are legitimate reasons unrelated to performance why such a situation might occur, and streaming media or large files is one of them.

Link to comment
Share on other sites
MSattler

MSattler   387

Posted
  • Author
Posted

the http server component generically adds that slow marker for all requests that stay open for longer than 1000ms, but sometimes there are legitimate reasons unrelated to performance why such a situation might occur, and streaming media or large files is one of them.

 

Interesting, would one possible use case be a user who is hard set to some Mbps quality setting, that they cannot currently achieve?  For instance, I have a family member using an iPad that at my house can set to 20Mbps.  When she goes to her own home, playback fails because the best she can get is about 5Mbps.  So would that then cause the slow response as well as the failed playback?  

 

Would it make sense to add additional logging for use cases like this so that Emby Server administrators can differentiate from issues such as that and other performance based issues?  To me, adding this would help you, and us users differentiate between performance problems, and end user problems.  The less end user problems we have, the happier people will be with Emby in general.

Link to comment
Share on other sites
Luke Emby Team

Luke   37008

Posted
Posted

Well, that and all playback http requests are going to take longer than 1s so they are always going to trigger the slow markings.

Link to comment
Share on other sites
MSattler

MSattler   387

Posted
  • Author
Posted

Well, that and all playback http requests are going to take longer than 1s so they are always going to trigger the slow markings.

 

 

Hmmmm any way to not mark playback requests as slow then?  Perhaps if it is a playback request mark it slow after 10 seconds?

Link to comment
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now
 Share
Go to topic listing
×
×
  • Create New...