Powershell Script to show # of SLOW entries per Server Log

[MSattler 387]

Cleaning this up to now add SLOW errors divided by the number of log hours, and by ffmpeg starts to get a better feel as to if increased playback is causing more of the SLOW Entries.

 

Function GET-EmbyLogSlows($filename) 

{

    $AppLine = (Select-string -path $filename.FullName -pattern "Application version:")

    $app = $AppLine -split " "

    $totallines = Get-Content $filename.FullName | Measure-Object -Line

    $stuff=Select-String -Path $filename.FullName -pattern SLOW | Measure-Object -Line

    $ffmpegStarts = Select-String -Path $filename.FullName -pattern ffmpeg.exe | Measure-Object -Line

    $ffmpegStopClean = Select-String -Path $filename.FullName -pattern "FFMpeg exited with code 0" | Measure-Object -Line 

    $logage = NEW-TIMESPAN -Start $filename.CreationTime -End $filename.LastWriteTime

    If ([iNT]$logage.hours -ne 0) {$SlowEntryPerHour = ([iNT]$stuff.lines/[iNT]$logage.Hours)} else {$SlowEntryPerHour=0}

    If ([iNT]$ffmpegstarts.lines -ne 0) {$SlowEntryPerFFMPegInstance =  ([iNT]$stuff.lines  / [iNT]$ffmpegstarts.lines )} else {$SlowEntryPerFFMPegInstance=0}

    $SlowEntryPerHour = "{0:N0}" -f $SlowEntryPerHour

    $SlowEntryPerFFMPegInstance = "{0:N0}" -f $SlowEntryPerFFMPegInstance

    #$SlowEntryPerHour = ([iNT]$stuff.lines/[iNT]$logage.Hours)

    #$SlowEntryPerFFMPegInstance =  ([iNT]$stuff.lines  / [iNT]$ffmpegstarts.lines )

    

   If ($logage.hours -ne 0)

   { 

             New-Object -TypeName pscustomobject -Property `

                @{ 

                     logname                    = $filename.basename

                     LogDate                    = $filename.creationTime.ToString('MM-dd-yyyy')

                     AppVersion                 = $app[6]

                     SlowEntries                = $stuff.lines

                     LogHours                   = $logage.Hours    

                     LogDay                     = $filename.creationTime.DayOfWeek

                     FFMpegStarts               = $ffmpegstarts.lines

                     FFMpegStopClean            = $ffmpegStopClean.lines

                     SlowEntriesPerHour         = $SlowEntryPerHour 

                     SlowEntriesPerFFMpegStart  = $SlowEntryPerFFMPegInstance

                  } | select logname,Logdate,LogDay,AppVersion,SlowEntries,LogHours, FFMpegStarts, FFMpegStopClean, SlowEntriesPerHour, SlowEntriesPerFFMpegStart

    }

}

 

$FileList = Get-ChildItem -Path $env:USERPROFILE\AppData\Roaming\Emby-Server\logs\server* -Force

 

$slowresults = foreach ($file in $filelist) {GET-EmbyLogSlows($file)}

 

$SlowResults | ft -autosize

Edited June 1, 2016 by MSattler

[Happy2Play 8238]

@@Luke where can I control how many logs Emby keeps?  This script, would be useful to run against logs to see which version has issues, and see if the number of slow entries is lowering with newer versions.

 

Thanks!

 

In your system.xml,  near the top you will see "<LogFileRetentionDays>3</LogFileRetentionDays>".  Shut down server - make the change -  Start server

[FrostByte 5041]

You could change your first line to something like this so it wouldn't need modifying by anyone (unless someone is using the old folder structure from MB3 still) and assuming they were logged in with the correct account

$FileList = Get-ChildItem -Path $env:USERPROFILE\AppData\Roaming\Emby-Server\logs -Force

Edited May 24, 2016 by FrostByte

[swhitmore 781]

This script, would be useful to run against logs to see which version has issues, and see if the number of slow entries is lowering with newer versions.

 

Thanks for making this. To do a fair comparison, you'll need to make sure the logs are for the same length of time.

[ebr 14902]

Thanks for making this. To do a fair comparison, you'll need to make sure the logs are for the same length of time.

 

There really would be no way to do a "fair" comparison unless you generated logs with the exact same activity happening in each session.  The time wouldn't necessarily be relevant.

 

However, if you come up with "0" at any point, you know you're good .

[spootdev 56]

Thanks for making this. To do a fair comparison, you'll need to make sure the logs are for the same length of time.

I have to disagree.  It really doesn't matter what the other old logs are doing.   If the current logs show the app is being slow and shitty then it's being slow and shitty and needs to be fixed.

[MSattler 387]

Ok updated with the recommendation earlier, and am including total number of lines in the log file.  Should give some relevance to number of SLOW errors in relation to the number of lines in the log.  Still think it goes to show that 3.0.5981 had some issues with slowness.

 

server-63599299200.txt from 05/20/2016 16:28:40 and 3.0.5973.0 has 70 Slow Entries with a log length of 75914

server-63599358552.txt from 05/21/2016 00:00:00 and 3.0.5981.0 has 140 Slow Entries with a log length of 71520

server-63599385600.txt from 05/22/2016 00:00:00 and 3.0.5981.0 has 1539 Slow Entries with a log length of 243502

server-63599472000.txt from 05/23/2016 00:00:00 and 3.0.5981.0 has 1430 Slow Entries with a log length of 73981

server-63599558400.txt from 05/23/2016 09:18:35 and 3.0.5981.0 has 21 Slow Entries with a log length of 30408

server-63599591918.txt from 05/23/2016 14:50:00 and 3.0.5984.0 has 83 Slow Entries with a log length of 57455

server-63599611802.txt from 05/23/2016 16:04:19 and 3.0.5984.0 has 16 Slow Entries with a log length of 8990

server-63599616261.txt from 05/24/2016 00:00:00 and 3.0.5985.0 has 113 Slow Entries with a log length of 42748

server-63599644800.txt from 05/24/2016 13:11:07 and 3.0.5985.0 has 1 Slow Entries with a log length of 78259

 

 

$FileList = Get-ChildItem -Path $env:USERPROFILE\AppData\Roaming\Emby-Server\logs -Force

 

foreach ($file in $filelist) 

{ 

    $AppLine = (Select-string -path $file.fullname -pattern "Application version:")

    $app = $AppLine -split " "

    $totallines = Get-Content $file.fullname | Measure-Object -Line

    

    $stuff=Select-String -Path $file.fullname -pattern SLOW | Measure-Object -Line

    $lastwrite = Get-Item $file.fullname | select LastWriteTime

  

   

    if ($stuff.lines -gt 300) 

    {  

       Write-Host ("$file from " + $lastwrite.LastWriteTime + " and " + $app[6] + " has " + $stuff.lines + " Slow Entries with a log length of " +  $totallines.lines + "% of SLOW to Lines is " +  ) -ForegroundColor Red

         

    }

    elseif ($stuff.lines -gt 0 -and $stuff.lines -le 500)

    {

       "$file from " + $lastwrite.LastWriteTime + " and " + $app[6] + " has " + $stuff.lines + " Slow Entries with a log length of " +  $totallines.lines   

    }

}

[MSattler 387]

There really would be no way to do a "fair" comparison unless you generated logs with the exact same activity happening in each session.  The time wouldn't necessarily be relevant.

 

However, if you come up with "0" at any point, you know you're good .

 

The script purposely excludes server logs with no errors.  My point with this is just to compare errors.  I suppose I could change it to just show all entries.

[MSattler 387]

Cleaned it up some:

 

 

 

Function GET-EmbyLogSlows($filename) 

{

    $AppLine = (Select-string -path $filename.FullName -pattern "Application version:")

    $app = $AppLine -split " "

    $totallines = Get-Content $filename.FullName | Measure-Object -Line

    $stuff=Select-String -Path $filename.FullName -pattern SLOW | Measure-Object -Line

    $logage = NEW-TIMESPAN -Start $filename.CreationTime -End $filename.LastWriteTime

    

   

    New-Object -TypeName pscustomobject -Property `

    @{

        logname     = $filename.basename

        LogDate     = $filename.creationTime.ToString('MM-dd-yyyy')

        AppVersion  = $app[6]

        SlowEntries = $stuff.lines

        LogHours    = $logage.Hours    

        LogDay      = $filename.creationTime.DayOfWeek

    } | select logname,Logdate,LogDay,AppVersion,SlowEntries,LogHours

}

 

$FileList = Get-ChildItem -Path $env:USERPROFILE\AppData\Roaming\Emby-Server\logs\server* -Force

 

$slowresults = foreach ($file in $filelist) {GET-EmbyLogSlows($file)}

 

$SlowResults | ft -autosize 

 

Edited May 24, 2016 by MSattler

[MSattler 387]

The new results based on the code above this post gives you this below.  I added the actual Day of the week as well.  We can see the high number of errors were on Saturday and Sunday.  Over time this will make it easier to compare number of errors, in relation to heaviest usage days.

 

Now.... if someone tells me what to look for to constitute usage, I could try and build a counter for that.  I think hours the log covers doesn't help as much as a true indicator of how busy the box is.  And number of lines didn't either, since there could be errors contacting IMDB, etc etc.

 

 

logname            LogDate      LogDay AppVersion SlowEntries LogHours

-------            -------      ------ ---------- ----------- --------

server-63599299200 05-20-2016   Friday 3.0.5973.0          70       16

server-63599358549 05-20-2016   Friday                      0        0

server-63599358552 05-20-2016   Friday 3.0.5981.0         140        7

server-63599385600 05-21-2016 Saturday 3.0.5981.0        1539       23

server-63599472000 05-22-2016   Sunday 3.0.5981.0        1430       23

server-63599558400 05-23-2016   Monday 3.0.5981.0          21        9

server-63599591915 05-23-2016   Monday                      0        0

server-63599591918 05-23-2016   Monday 3.0.5984.0          83        5

server-63599611802 05-23-2016   Monday 3.0.5984.0          16        1

server-63599616259 05-23-2016   Monday                      0        0

server-63599616261 05-23-2016   Monday 3.0.5985.0         113        7

server-63599644800 05-24-2016  Tuesday 3.0.5985.0           1       17

Edited May 24, 2016 by MSattler

[MSattler 387]

This also looks at number of ffmpeg calls made, and number of clean ffmpeg stops, with ffmpeg coming back with a exit 0.

 

 

Function GET-EmbyLogSlows($filename) 

{

    $AppLine = (Select-string -path $filename.FullName -pattern "Application version:")

    $app = $AppLine -split " "

    $totallines = Get-Content $filename.FullName | Measure-Object -Line

    $stuff=Select-String -Path $filename.FullName -pattern SLOW | Measure-Object -Line

    $ffmpegStarts = Select-String -Path $filename.FullName -pattern ffmpeg.exe | Measure-Object -Line

    $ffmpegStopClean = Select-String -Path $filename.FullName -pattern "FFMpeg exited with code 0" | Measure-Object -Line 

    $logage = NEW-TIMESPAN -Start $filename.CreationTime -End $filename.LastWriteTime

    

   

    New-Object -TypeName pscustomobject -Property `

    @{

        logname           = $filename.basename

        LogDate           = $filename.creationTime.ToString('MM-dd-yyyy')

        AppVersion        = $app[6]

        SlowEntries       = $stuff.lines

        LogHours          = $logage.Hours    

        LogDay            = $filename.creationTime.DayOfWeek

        FFMpegStarts      = $ffmpegstarts.lines

        FFMpegStopClean   = $ffmpegStops.lines

    } | select logname,Logdate,LogDay,AppVersion,SlowEntries,LogHours, FFMpegStarts, FFMpegStopClean

}

 

$FileList = Get-ChildItem -Path $env:USERPROFILE\AppData\Roaming\Emby-Server\logs\server* -Force

 

$slowresults = foreach ($file in $filelist) {GET-EmbyLogSlows($file)}

 

$SlowResults | ft -autosize 

[CBers 6766]

Nice work Marcus

[MrWebsmith 598]

yup... i finally tried it out.. good stuff..  i changed my log retention so i can track this data a bit further back... moving fwd..

 

 https://www.dropbox.com/s/txp4vs0vxgt5qh9/psoutput.jpg?dl=0

[CBers 6766]

A quicker way of searching through a server log.

 

[MSattler 387]

Would have been cool to see your slowentries for 5981.

 

I am interested to see what this weekend looks like.

 

 

 

 

A quicker way of searching through a server log.

 

[FrostByte 5041]

If anyone is looking to have a batch file to go along with the PowerShell script this one should work.  Just name it the same as your ps1 file containing the code above (i.e. if you have CheckForSlowEntries.ps1 then name the batch file CheckForSlowEntries.bat) and place in the same folder as the ps1.  Then just execute the bat file

​

@ECHO OFF
PowerShell -NoProfile -ExecutionPolicy Bypass -Command "& '%~dpn0.ps1' -Verb RunAs"
pause

[Happy2Play 8238]

Any reason I would get this error multiple time?

New-Object : Missing an argument for parameter 'Property'. Specify a parameter of type 'System.Collections.IDictionary' and try again.
At D:\Scripts\Scan_Logs.ps1:23 char:41
+     New-Object -TypeName pscustomobject -Property `
+                                         ~~~~~~~~~
    + CategoryInfo          : InvalidArgument: ( [New-Object], ParameterBindingException
    + FullyQualifiedErrorId : MissingArgument,Microsoft.PowerShell.Commands.NewObjectCommand

Then

logname Logdate LogDay AppVersion SlowEntries LogHours FFMpegStarts FFMpegStopClean
------- ------- ------ ---------- ----------- -------- ------------ ---------------

[Happy2Play 8238]

Something with the format on line 23.  Google and trial and error to make it work.

Beta

logname            LogDate       LogDay AppVersion SlowEntries LogHours FFMpegStarts FFMpegStopClean
-------            -------       ------ ---------- ----------- -------- ------------ ---------------
server-63599471999 05-21-2016  Saturday 3.0.5983.0         224       23           49
server-63599558399 05-22-2016    Sunday 3.0.5983.0          26       13            0
server-63599606244 05-23-2016    Monday                      0        0            0
server-63599606249 05-23-2016    Monday 3.0.5985.0          72       10           88
server-63599644799 05-23-2016    Monday 3.0.5985.0          63       14            0
server-63599697265 05-24-2016   Tuesday                      0        0            0
server-63599697327 05-24-2016   Tuesday 3.0.5985.0          66        9           37
server-63599731199 05-24-2016   Tuesday 3.0.5985.0          16        2            0
server-63599741952 05-25-2016 Wednesday                      0        0            0
server-63599742675 05-25-2016 Wednesday 3.0.5989.0          72       14            1

Stable

logname            LogDate       LogDay AppVersion SlowEntries LogHours FFMpegStarts FFMpegStopClean
-------            -------       ------ ---------- ----------- -------- ------------ ---------------
server-63599391479 05-21-2016  Saturday 3.0.5970.0          50       22            2
server-63599472001 05-22-2016    Sunday 3.0.5970.0          25       23            0
server-63599558401 05-23-2016    Monday 3.0.5970.0           4       23            0
server-63599644801 05-24-2016   Tuesday 3.0.5970.0           0        0            0
server-63599646420 05-24-2016   Tuesday 3.0.5971.0          32       23            1
server-63599731201 05-25-2016 Wednesday 3.0.5971.0          68       12            2
server-63599775460 05-25-2016 Wednesday                      0        0            0
server-63599775464 05-25-2016 Wednesday 3.0.5972.0           7        5            1

 

Edited May 26, 2016 by Happy2Play

[swhitmore 781]

Sorry guys, I haven't really used Powershell before. Would someone mind quickly explaining the best way to run this script on a scheduled task? Thank you.

[CBers 6766]

@@swhitmore

 

 

If anyone is looking to have a batch file to go along with the PowerShell script this one should work.  Just name it the same as your ps1 file containing the code above (i.e. if you have CheckForSlowEntries.ps1 then name the batch file CheckForSlowEntries.bat) and place in the same folder as the ps1.  Then just execute the bat file

​

@ECHO OFF
PowerShell -NoProfile -ExecutionPolicy Bypass -Command "& '%~dpn0.ps1' -Verb RunAs"
pause

 

I assume you then just use the bat file in your scheduled task.

Edited May 26, 2016 by CBers

[CBers 6766]

Something with the format on line 23.  Google and trial and error to make it work.

 

Care to elaborate.

[FrostByte 5041]

I was getting the same and ended up making the following change to the end of this line, basically just removed special character and moved next line up

    New-Object -TypeName PSCustomObject -Property @{

[MSattler 387]

Sorry guys, I haven't really used Powershell before. Would someone mind quickly explaining the best way to run this script on a scheduled task? Thank you.

 

run a scheduled task and have it call powershell -file "c:\somedirectory\filename.ps1"

 

That should do it.

[MSattler 387]

Here is the latest:

 

 

Function GET-EmbyLogSlows($filename) 

{

    $AppLine = (Select-string -path $filename.FullName -pattern "Application version:")

    $app = $AppLine -split " "

    $totallines = Get-Content $filename.FullName | Measure-Object -Line

    $stuff=Select-String -Path $filename.FullName -pattern SLOW | Measure-Object -Line

    $ffmpegStarts = Select-String -Path $filename.FullName -pattern ffmpeg.exe | Measure-Object -Line

    $ffmpegStopClean = Select-String -Path $filename.FullName -pattern "FFMpeg exited with code 0" | Measure-Object -Line 

    $logage = NEW-TIMESPAN -Start $filename.CreationTime -End $filename.LastWriteTime

    

   

    New-Object -TypeName pscustomobject -Property `

    @{

        logname           = $filename.basename

        LogDate           = $filename.creationTime.ToString('MM-dd-yyyy')

        AppVersion        = $app[6]

        SlowEntries       = $stuff.lines

        LogHours          = $logage.Hours    

        LogDay            = $filename.creationTime.DayOfWeek

        FFMpegStarts      = $ffmpegstarts.lines

        FFMpegStopClean   = $ffmpegStopClean.lines

    } | select logname,Logdate,LogDay,AppVersion,SlowEntries,LogHours, FFMpegStarts, FFMpegStopClean

}

 

$FileList = Get-ChildItem -Path $env:USERPROFILE\AppData\Roaming\Emby-Server\logs\server* -Force

 

$slowresults = foreach ($file in $filelist) {GET-EmbyLogSlows($file)}

 

$SlowResults | ft -autosize 

[MSattler 387]

@@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!