MSattler 387 Posted May 23, 2016 Share Posted May 23, 2016 (edited) 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 3 Link to comment Share on other sites More sharing options...
Happy2Play 8238 Posted May 23, 2016 Share Posted May 23, 2016 @@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 1 Link to comment Share on other sites More sharing options...
FrostByte 5041 Posted May 24, 2016 Share Posted May 24, 2016 (edited) 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 1 Link to comment Share on other sites More sharing options...
swhitmore 781 Posted May 24, 2016 Share Posted May 24, 2016 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. Link to comment Share on other sites More sharing options...
ebr 14902 Posted May 24, 2016 Share Posted May 24, 2016 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 . Link to comment Share on other sites More sharing options...
spootdev 56 Posted May 24, 2016 Share Posted May 24, 2016 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. Link to comment Share on other sites More sharing options...
MSattler 387 Posted May 24, 2016 Author Share Posted May 24, 2016 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 } } 2 Link to comment Share on other sites More sharing options...
MSattler 387 Posted May 24, 2016 Author Share Posted May 24, 2016 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. Link to comment Share on other sites More sharing options...
MSattler 387 Posted May 24, 2016 Author Share Posted May 24, 2016 (edited) 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 Link to comment Share on other sites More sharing options...
MSattler 387 Posted May 24, 2016 Author Share Posted May 24, 2016 (edited) 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 Link to comment Share on other sites More sharing options...
MSattler 387 Posted May 25, 2016 Author Share Posted May 25, 2016 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 1 Link to comment Share on other sites More sharing options...
CBers 6766 Posted May 25, 2016 Share Posted May 25, 2016 Nice work Marcus 1 Link to comment Share on other sites More sharing options...
MrWebsmith 598 Posted May 25, 2016 Share Posted May 25, 2016 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 1 Link to comment Share on other sites More sharing options...
CBers 6766 Posted May 25, 2016 Share Posted May 25, 2016 A quicker way of searching through a server log. 1 Link to comment Share on other sites More sharing options...
MSattler 387 Posted May 25, 2016 Author Share Posted May 25, 2016 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. 1 Link to comment Share on other sites More sharing options...
FrostByte 5041 Posted May 25, 2016 Share Posted May 25, 2016 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 1 Link to comment Share on other sites More sharing options...
Happy2Play 8238 Posted May 25, 2016 Share Posted May 25, 2016 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 ------- ------- ------ ---------- ----------- -------- ------------ --------------- Link to comment Share on other sites More sharing options...
Happy2Play 8238 Posted May 26, 2016 Share Posted May 26, 2016 (edited) 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 Link to comment Share on other sites More sharing options...
swhitmore 781 Posted May 26, 2016 Share Posted May 26, 2016 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. Link to comment Share on other sites More sharing options...
CBers 6766 Posted May 26, 2016 Share Posted May 26, 2016 (edited) @@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 1 Link to comment Share on other sites More sharing options...
CBers 6766 Posted May 26, 2016 Share Posted May 26, 2016 Something with the format on line 23. Google and trial and error to make it work. Care to elaborate. Link to comment Share on other sites More sharing options...
FrostByte 5041 Posted May 26, 2016 Share Posted May 26, 2016 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 @{ 1 Link to comment Share on other sites More sharing options...
MSattler 387 Posted May 26, 2016 Author Share Posted May 26, 2016 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. 1 Link to comment Share on other sites More sharing options...
MSattler 387 Posted May 26, 2016 Author Share Posted May 26, 2016 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 Link to comment Share on other sites More sharing options...
MSattler 387 Posted May 26, 2016 Author Share Posted May 26, 2016 @@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! Link to comment Share on other sites More sharing options...
Recommended Posts
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 accountSign in
Already have an account? Sign in here.
Sign In Now