LogSpam + possible speedups

[ExSport]

v5.1.3 Build: 987e16d79 (2015-04-27)

File is ok on renderer so making possible/configurable to not hide similar files will be great. Why switching to ffmpeg for picture?

...
INFO  11:44:49.872 [Library Scanner] Error parsing image (K:\_FOTO\_Filip Nexus4\IMG_20130214_190754.jpg) with Sanselan, switching to FFmpeg.
INFO  11:44:49.874 [Library Scanner] The file K:\_FOTO\_Filip Nexus4\IMG_20130214_190754.jpg could not be parsed. It will be hidden
INFO  11:44:49.875 [Library Scanner] Error parsing image (K:\_FOTO\_Filip Nexus4\IMG_20130214_190754.jpg) with Sanselan, switching to FFmpeg.
INFO  11:44:50.391 [Library Scanner] Error parsing image (K:\_FOTO\_Filip Nexus4\IMG_20130214_190812.jpg) with Sanselan, switching to FFmpeg.
INFO  11:44:50.393 [Library Scanner] The file K:\_FOTO\_Filip Nexus4\IMG_20130214_190812.jpg could not be parsed. It will be hidden
INFO  11:44:50.394 [Library Scanner] Error parsing image (K:\_FOTO\_Filip Nexus4\IMG_20130214_190812.jpg) with Sanselan, switching to FFmpeg.
INFO  11:44:51.005 [Library Scanner] Error parsing image (K:\_FOTO\_Filip Nexus4\IMG_20130214_190820.jpg) with Sanselan, switching to FFmpeg.
INFO  11:44:51.006 [Library Scanner] The file K:\_FOTO\_Filip Nexus4\IMG_20130214_190820.jpg could not be parsed. It will be hidden
INFO  11:44:51.007 [Library Scanner] Error parsing image (K:\_FOTO\_Filip Nexus4\IMG_20130214_190820.jpg) with Sanselan, switching to FFmpeg.
INFO  11:45:25.198 [Library Scanner] Error parsing image (K:\_FOTO\_Filip Nexus4\IMG_20130214_205915.jpg) with Sanselan, switching to FFmpeg.
INFO  11:45:25.200 [Library Scanner] The file K:\_FOTO\_Filip Nexus4\IMG_20130214_205915.jpg could not be parsed. It will be hidden
INFO  11:45:25.201 [Library Scanner] Error parsing image (K:\_FOTO\_Filip Nexus4\IMG_20130214_205915.jpg) with Sanselan, switching to FFmpeg.
...

What's this spam? I thought it is related to XBOX only:-)

...
DEBUG 12:07:02.919 [Library Scanner] GlobalIdRepo: removing id 2256 - IMG_20141212_153657.jpg
DEBUG 12:07:02.920 [Library Scanner] GlobalIdRepo: removing id 2257 - IMG_20141212_153659.jpg
DEBUG 12:07:02.920 [Library Scanner] GlobalIdRepo: removing id 2262 - IMG_20141212_162043.jpg
...
DEBUG 12:44:26.668 [Library Scanner] GlobalIdRepo: removing id 9168 - 00257.MTS
DEBUG 12:44:26.668 [Library Scanner] GlobalIdRepo: removing id 9171 - 00258.MTS
DEBUG 12:44:26.668 [Library Scanner] GlobalIdRepo: removing id 9174 - 00259.MTS
...

When creating thumbs I spotted messages like "Consider increasing the value for the 'analyzeduration' and 'probesize' options"

By default first one is 5000000=5s and other one is 5000000bytes (plus -stats is on by default). What about to speed up things and use 0 and 32 for max speed? Also creating one thumb for test mkv file generates 12KB of spam in log. What about to use -v quiet/fatal/... to reduce it? What about to use all three/four params not for thumbs generation only? It should be useful for "maybe" faster rewinding, start of file transcoding, cleaner logs, etc... These are some from my spots in log when I started scanning my shared files. By the way scanning is still in progress and DB size is already 750MB. What exactly is stored there? When file is updated, old record is updated or new one added with not deleting old one? What about the DB access. Is it fully cached in memory or how queries are done (to disk or memory)? Useful to know how big heap memory should be set. Thanks! ExSport

[ExSport]

Some update to this: heap size use is set to 1200 so UMS allocates something less to this value. Scanning library generated 1,1GB DB file so it seems it failed due to insufficient memory. Unfortunately I don't have logs because parents restarted computer so it was overwritten :-1: I must test creating 1GB DB again and lower heap size to e.g. 700 if UMS will start because noone can't answer me how DB queries works :-) If all is cached in memory or not because owning lot of pictures, holiday videos, HD movies etc. generates me huge DB and I am not sure if I rescan folders again if it will not start growing again also for files which were already indexed. Who knows? @SubJunk @skeptical @SharkHunter @valib ? One holiday trip with HD camera creates about 600 TS and few hundreds of JPG files so the DB grows enormously. Unfortunately I am not a general user :-1: :+1:

[SubJunk]

@ExSport if the DB is that big it's probably a bug in how we store DB information, so logs will be useful

[ExSport]

@SubJunk I will try to record somehow but somewhere in the middle of scanning log had few hundreds of MegaBytes. I think most of the place in db are thumbs? Will try to disable them because scanning e.g. (never counted them) 50'000 pics and 7'000 videos should be the culprit of huge db (if thumbs are stored) and also FFmpeg spamming is also culprit of huge log when scanning files :-)

[taconaut]

@ExSport If you want to have a look at the DB, I recommend DbVisualizer. Use following to configure the connection: Database driver='h2 embedded' URL='jdbc:h2:C:\ProgramData\UMS\database/medias' User='sa' Pwd=''

Thumbs are being stored in the THUMB column of the FILES table.

[ExSport]

@taconaut Thanks for tip! I tried shortly and I see DB with "INFORMATION_SCHEMA" and "PUBLIC" (empty) schema. I tried to find what you mentioned and also some filenames, codecs etc. but without success. I know MS SQL but here I was little lost, will try look again later. @SubJunk Definitely thumbs are stored in DB as when I disabled image and video thumbs , DB was much smaller at time scaning was stucked [https://github.com/UniversalMediaServer/UniversalMediaServer/issues/554] so maybe it will be better to store them outside DB with link to external file? It should avoid huge DB size but I know it will be little slower but probably more stable. I shared and scanned 9'000 pictures + some videos from Australia trip taken by photo camera which never finished due to cr2 files but DB stucked on 400MB what is unusable (sharing all should generate 10times larger DB I suppose). For now I have to untick showing image thumbs in GUI (hopefully it will disable thumbs generation and storing it in DB) Any thoughts? EDIT: Unchecking image thumbs still doesn't help in not loading and freezing dcrawMS process :-1:

[ExSport]

@taconaut You mentioned FILES...I see this in file c:\ProgramData\UMS\database\ medias.trace.db:

05-05 18:24:11 jdbc[3]: exception
org.h2.jdbc.JdbcSQLException: Table "FILES" not found; SQL statement:
SELECT count(*) FROM FILES [42102-187]
05-05 18:24:11 jdbc[3]: exception
org.h2.jdbc.JdbcSQLException: Table "FILES" not found; SQL statement:
DROP TABLE FILES [42102-187]

Seems not standard behavior. EDIT: OK it seems trace is created before DB exists so no real problem.

[taconaut]

@ExSport I think the trace.db file contains the DB logs. You might have to download the 1.4.187 version of the h2.jar and specify it for h2 embedded under tools/driver manager. You should find the FILES table under medias/public/table then.

Btw in mlx thumbs and covers are stored as you propose in the file system with the path in the DB and I haven't seen any issues with DB size.

[ExSport]

@taconaut Thanks! Replacing h2.jar with the latest one from [http://www.h2database.com/html/main.html] fixed it! Now I can debug DB more easily :+1:

[taconaut]

@ExSport Cool, you're welcome :)

[ExSport]

Other tips for speed improvements: What about to make indexing/thumbs generation/etc. multithreaded? Right now only one ffmpeg process is started for thumbs generation and until it finishes it waits for other file. I thing e.g. 10 threads should help speed up process without affecting HDD limits? Also I suppose MediaInfo parsing is also single threaded but maybe I am wrong (not spent on it much time)

[ExSport]

@SubJunk It seems UMS doesn't use multithreading for FFMPEG. By default -threads param is 1 (minimally for MPEG2 output) so CPU usage is about 40% and video stutter. It seems for mpeg2 output -slices param by default is not definitely 1 from my tests so it can be omitted perhaps but not -threads as it generates 38fps for tested video (1080p) for first 1min where there is no "action" so later in movie CPU is not fully utilized so realtime encoding is impossible. Adding -threads 4 to command line generates about 70% CPU and 66fps what is much better for realtime encoding. I also played with -preset ultrafast/fast/slow etc. and for MPEG2 output there was almost no difference but for x264 it can be different story so it is ok to be omitted for MPEG2 but tested with x264. But I definitely recommend -tune zerolatency as it helps to play file on renderer almost immediately and also FF/RW is more stable.

[SubJunk]

@ExSport FFmpeg shouldn't use the -threads param by default, since FFmpeg is good at automatically detecting threads. So that's either a UMS bug or a setting you forgot about, is it the same with a clean install?

[ExSport]

@SubJunk Check the latest FFmpeg code/discussion/documentation and you will find threads=1 by default. All my testing were from command line (x64) and I am sure for mpeg2 output when threads param is missing it is used as 1 by default. I searched for default settings and found some older posts where FFmpeg is detecting threads automatically [-threads 0] and also slices but it also depends on the output format as mpeg2 can be different from x264 etc. In another discussion there is info that by default it is nr. of cores minus 1 so maybe my dual core with multithreading = 4 threads are count as 2-1=1. But latest posts talk about default settings -threads 1 what also shows my own tests. It has nothing to do with my UMS settings as I am using 4 threads but in log there is no -threads param so multithreading is disabled. I haven't tested x264 output unfortunately. Maybe for this output default threads is not 1. Also I am sure -slices is to not 1 when omitted because adding threads 4 and slices 1 generates same speed as when threads and/or slices params are missing. Also for info, in past we had global MEncoder settings. I implemented custom settings on renderer level for MEncoder. Later Custom FFmpeg settings was implemented on renderer level but there is no custom settings how to set it globally. At time when FFmpeg is default engine it will be great to have it:-)

[valib]

@ExSport tested current implementation and FFmpeg uses both my CPU cores on about 65% and the rest is for Java and other processes. The -threads in the command line are not specified. But it is an old notebook with Intel T5500, 1.6 MHz CPU.

EDIT: changing - threads to 4, 6 makes no difference. For me the CPU is always utilized on 100% until the cache is not full. Than it drops to about 25%.

EDIT2: FFmpeg is compiled with --disable-w32threads but I am running UMS on the 32-bit Windows. So I have no idea how it works.

[ExSport]

Tests from yesterday where one ffmpeg64 never took more than 50% CPU without -threads param and 70% with -threads 4/8 (two ffmpeg were able to utilize whole CPU):

"C:\Program Files (x86)\Universal Media Server\win32\ffmpeg64.exe" -y -loglevel info -i K:\2014-0~1\_DOKUM~1\KOSMOS~1\04-OBL~1.MKV -map 0:v -map 0:a:1 -bufsize 7000000 -maxrate 34000000 -g 5 -q:v 1 -qmin 2 -qmax 3 -c:a copy -c:v mpeg2video -f vob -threads 4 k:\xxx4.mpg
ffmpeg version N-69972-g6c91afe Copyright (c) 2000-2015 the FFmpeg developers
... compiled with --disable-w32threads ...
frame= 3015 fps= 67 q=1.0 Lsize=   97634kB time=00:01:00.76 bitrate=13161.8kbits/s dup=1508 drop=0
video:95007kB audio:1424kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 1.246920%

"C:\Program Files (x86)\Universal Media Server\win32\ffmpeg64.exe" -y -loglevel info -i K:\2014-0~1\_DOKUM~1\KOSMOS~1\04-OBL~1.MKV -map 0:v -map 0:a:1 -bufsize 7000000 -maxrate 34000000 -g 5 -q:v 1 -qmin 2 -qmax 3 -c:a copy -c:v mpeg2video -f vob -threads 1 k:\xxx1.mpg
ffmpeg version N-69972-g6c91afe Copyright (c) 2000-2015 the FFmpeg developers
... compiled with --disable-w32threads ...
frame= 3013 fps= 39 q=1.0 Lsize=   96534kB time=00:01:00.76 bitrate=13013.5kbits/s dup=1507 drop=0
video:93922kB audio:1424kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 1.246240%

"C:\Program Files (x86)\Universal Media Server\win32\ffmpeg64.exe" -y -loglevel info -i K:\2014-0~1\_DOKUM~1\KOSMOS~1\04-OBL~1.MKV -map 0:v -map 0:a:1 -bufsize 7000000 -maxrate 34000000 -g 5 -q:v 1 -qmin 2 -qmax 3 -c:a copy -c:v mpeg2video -f vob x:\xxx.mpg
ffmpeg version N-69972-g6c91afe Copyright (c) 2000-2015 the FFmpeg developers
... compiled with --disable-w32threads ...
frame= 2163 fps= 37 q=1.0 Lsize=   70072kB time=00:00:43.64 bitrate=13151.3kbits/s dup=1082 drop=0
video:68187kB audio:1023kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 1.245865%

I repeated these tests 20x with consistent results but today I don't understand it but omitting -threads param behaves like -threads 0 [auto] which is about 7fps slower than 4 or 8 (auto is not so optimal). Only once today I was able to reproduce slow 39fps with omitted -threads param so I will try to reproduce it again but with -loglevel debug which shows detected logical cores if there is not problem (sometimes no multithreading is detected???) Meanwhile I spotted bug in FFMPEG where MediaInfo detects MKV as 25fps but FFmpeg as 50fps so final 1080p file is generated as 50fps what is impossible on my quad core CPU (Core2-Quad 2.66Ghz)

-loglevel verbose & debug (funny that adding debug level, FFmpeg shows correct fps hidden by default but for other file it shows 0 so not useful): Debug:

Duration: 00:43:43.40, start: 0.000000, bitrate: 5713 kb/s
  Stream #0:0, 25, 1/1000: Video: h264 (High), yuv420p(tv, bt470bg, left), 1920x1080 (1920x1088) [SAR 1:1 DAR 16:9], 1/50, 50 fps, 50 tbr, 1k tbn, 50 tbc (default)

Verbose:

 Duration: 00:43:43.40, start: 0.000000, bitrate: 5713 kb/s
   Stream #0:0: Video: h264 (High), yuv420p(tv, bt470bg), 1920x1080 (1920x1088) [SAR 1:1 DAR 16:9], 50 fps, 50 tbr, 1k tbn, 50 tbc (default)

MediaInfo:

Format                                   : AVC
Format/Info                              : Advanced Video Codec
Format profile                           : High@L4
Format settings, CABAC                   : Yes
Format settings, ReFrames                : 3 frames
Format settings, GOP                     : M=4, N=32
Codec ID                                 : V_MPEG4/ISO/AVC
Duration                                 : 43mn 43s
Bit rate mode                            : Variable
Bit rate                                 : 5 024 Kbps
Maximum bit rate                         : 40.0 Mbps
Width                                    : 1 920 pixels
Height                                   : 1 080 pixels
Display aspect ratio                     : 16:9
Frame rate mode                          : Constant
Frame rate                               : 25.000 fps
Standard                                 : Component
Color space                              : YUV
Chroma subsampling                       : 4:2:0
Bit depth                                : 8 bits
Scan type                                : Interlaced
Scan order                               : Top Field First
Bits/(Pixel*Frame)                       : 0.097
Stream size                              : 1.53 GiB (88%)
Default                                  : Yes
Forced                                   : No
Color range                              : Limited
Color primaries                          : BT.601 PAL
Transfer characteristics                 : BT.470 System B, BT.470 System G
Matrix coefficients                      : BT.601

It seems auto threading is not working correctly at all circumstances but forcing -threads 4 fixed slow encoding in 100%. Also forcing output fps from MediaInfo should be the fix for incorrect fps detected by FFmpeg (maybe detection problem with interlaced source?)

[ExSport]

@valib @SubJunk : Command is generated for Panasonic TV but I forced MPEG2 instead of x264 encoding in renderer conf because my CPU can't do 1080p in realtime with MEncoder and x264 (almost all files has full or forced subs)

[valib]

@ExSport maybe it is the ffmpeg64 bug. I tested the 32-bit version. I will test it on my PC with 64-bit Windows.

[ExSport]

@valib Maybe it is also connected to specifics of tested file. I will try other files later. Now I tested 32bit ffmpeg with similar results. Using -threads 4 or 8 and -slices 32 makes encoding fast as possible (same for 32/64 version). Omitting these params is sometimes little bit slower (about 5fps) and sometimes much slower (speed same as -threads 1 or -slices 1 is used = 25-50% slower) Weird that sometimes speed is as -threads 0 is used and other times as -threads 1 (when -threads is omitted) so it seems it is dynamic to file type and also in time the behavior changes (bug?). At all times CPU was idle when I started testing so nonmultithreaded results were not due CPU overload. I was never able to fully utilize 100% CPU as also other users mentioned in FFmpeg discussion where other users recommend to run more FFmpeg processes as it is not so well optimized for multithreading and it differ betweeb versions... I suppose for most consistend and maximally fast and stable encoding we should use -threads nr.of cores defined in GUI + maybe -slices 32 for maximum speed + -r fps for avoiding wrong fps output detected by FFmpeg right now. Also omitting -threads sometimes enables autodetection and sometimes it sets threads to 1 but at all times it is slower than defining logical cores manually. EDIT: Forgot to mention -tune zerolatency as a key param for better streaming response as renderer need not wait for key frame few secs (great for FF/RW). I suppose it has more advantaged than cons.

[SubJunk]

@ExSport I did testing a while ago and found it was fastest without threads specified. I'm not even sure if the -threads option does anything now anyway, since the FFmpeg documentation lists its only possible value as "auto". So it seems we are getting different results and we need to find out why before doing any changes.

[ExSport]

@SubJunk I suppose it is also not consistent due to different files. There is no auto value string as FFmpeg forum say and also my testing with -threads auto ignores it as wrong argument. Auto is represented by -threads 0 but as I said, for tested file it was inconsistent and also always slower. Also users in discussion writes it differs for different files. Maybe my behavior is also due wrong fps detection so outputting 50fps can have different behavior as with 25fps and also different for x264 and mpeg2 encoding. I also tested another file with correct 25fps output, non interlaced mkv file and CPU utilization with default settings (without threads param) was much better so as I said, testing only one type of file is not relevant. In FFmpeg discussion there is info auto is not so optimal and also for some files threads 1 can be used by default so I recommended to use nr. of cores defined in UMS config as it seems to me most reliable across different files, output codecs and systems. FFmpeg manual is quite outdated in this direction I think so searching for FFmpeg + threads + slices for last year will return more recent info. Anyway I think it is nothing against to use tune zerolatency param and fixing wrong fps detection by forcing fps from mediainfo ;-) What do you think?

[ExSport]

Some update about using -r -threads -slices? :+1:

[ExSport]

Old issue, it should not be relevant anymore...