Compile error plugins

[mulder77]

OK, I added some links to my locally built libraries:

$ ldd libADM_ve_x264_*|grep x264
libADM_ve_x264_other.so:
        libx264.so.128 => /lib64/libx264.so.128 (0x00007f54175bb000)
libADM_ve_x264_qt4.so:
        libx264.so.128 => /lib64/libx264.so.128 (0x00007fc256bbc000)

Here is the link:

$ ls -l /lib64/libx264.so.128
lrwxrwxrwx 1 root root 29 Sep  6 12:47 /lib64/libx264.so.128 -> /usr/local/lib/libx264.so.128

Information about the compiled libraries:

$ file /usr/local/lib/libx264.so.128
/usr/local/lib/libx264.so.128: ELF 64-bit LSB shared object, x86-64, version 1 (SYSV), dynamically linked, BuildID[sha1]=0xc1eddc66eaf59f462febe98ef2f4283631d23190, not stripped

But still: performance still drops dramatically after appr. 30 secs of encoding.

[Jan Gruuthuse]

>8 >8
Cores: The options in the tab are greyed out, I cannot modify them.

In [Threading ]
Select (Ã,°) Custom, see attachment. Weird it is using 4 cores and additional 4 virtual cores (Hyperthreading) Should not give any advantage as the 4 cores are already maxed out, the 4 virtual cores are probably slowing things down. Did you lower prioritisation on encoding (2 steps lower)

[Jan Gruuthuse]

If you run attached script, script to decode /proc/cpuinfo, from terminal it should tell you:

This system has one physical CPU,
and 4 logical CPUs.
For every physical CPU there are 4 cores.
The CPU is a Intel(R) Core(TM) i5-2500K CPU @ 3.30GHz with 6144 KB cache

If you have more logical CPU's then physical, HT is enabled, above output would show not enabled.
Would compiling with make -j8 cause this behavior?

according to Intel both CPU's have no IntelÃ,® Hyper-Threading Technology enabled:
IntelÃ,® Coreâ„¢ i5-2400S Processor
IntelÃ,® Coreâ„¢ i5-2500K Processor

PS: Simultaneous multithreading: SMT or Intel Hyper-Threading: HT

[mulder77]

Jan, thanks for clarification. I was looking into the preferences of the x264 encoder.

I found the settings and modified them, but I still see 8 threads running during encoding. I set the value to 2, no difference.

The script does this output:
This system has one physical CPU,
and 4 logical CPUs.
For every physical CPU there are 4 cores.
The CPU is a Intel(R) Core(TM) i5-2400S CPU @ 2.50GHz with 6144 KB cache

For your understanding: I was doing re-encodings from my TV recordings for several months on this platform, running on r8025 (I assume). They were totally ok. Started at ~30-35 fps and kept there w/o problems.

As I can see, performance drops by ~90% at more or less exactly 30s of elapsed encoding time. Looks to me like some sort of buffer being filled up or something. But that's just something I can only guess about.

[Jan Gruuthuse]

I've uploaded 1:30 minutes of 720p recording: 720ptest.ts (168 MB)
Could you download and check if the same is going on when you re-encode that clip?
Could you then save that project in tinypy and attach this to your posting.
I could then run the same job and see if same behavior happens here.
How do you check/see the nÃ,° of running threads? I Only use conky to monitor the cpu.

[mulder77]

Jan, thanks for your nice support so far.
I downloaded that recording and applied my usual filters, settings etc.

Encoding is still ongoing, but this time it started at 3-4 fps right from the start.

To control CPU usage I simply run "top", by pressing "H" it'll show you threads separately. Looks like this:

Code Select Expand

# top

top - 23:18:11 up 23 days,  3:44,  2 users,  load average: 6.17, 3.38, 1.61
Tasks: 487 total,   7 running, 480 sleeping,   0 stopped,   0 zombie
Cpu0  :  0.5%us,  5.0%sy, 91.5%ni,  0.0%id,  0.0%wa,  3.0%hi,  0.0%si,  0.0%st
Cpu1  :  1.5%us,  4.5%sy, 85.6%ni,  0.0%id,  0.0%wa,  8.4%hi,  0.0%si,  0.0%st
Cpu2  :  0.5%us,  0.5%sy, 98.0%ni,  0.5%id,  0.0%wa,  0.5%hi,  0.0%si,  0.0%st
Cpu3  :  6.0%us,  0.5%sy, 93.5%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  16124812k total, 15953148k used,   171664k free,   338084k buffers
Swap:        0k total,        0k used,        0k free, 13305940k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P SWAP COMMAND                                                                 
23338 vnc       30  10 1667m 182m  36m R 76.7  1.2   2:41.62 2    0 avidemux3_qt4                                                           
23339 vnc       30  10 1667m 182m  36m R 65.8  1.2   2:27.32 2    0 avidemux3_qt4                                                           
23335 vnc       30  10 1667m 182m  36m R 65.3  1.2   2:45.75 2    0 avidemux3_qt4                                                           
23336 vnc       30  10 1667m 182m  36m R 59.9  1.2   1:14.89 1    0 avidemux3_qt4                                                           
23337 vnc       30  10 1667m 182m  36m R 55.4  1.2   3:06.56 0    0 avidemux3_qt4                                                           
23340 vnc       30  10 1667m 182m  36m R 51.0  1.2   2:40.26 1    0 avidemux3_qt4                                                           
23342 vnc       20   0 1667m 182m  36m S  5.9  1.2   0:21.97 3    0 avidemux3_qt4                                                           
1061 markus    20   0 2526m 447m 1776 S  3.5  2.8 444:49.03 0    0 tvheadend                                                               
23341 vnc       20   0 1667m 182m  36m S  1.5  1.2   0:05.10 1    0 avidemux3_qt4                                                           
23254 vnc       20   0 1667m 182m  36m S  1.0  1.2   0:09.77 0    0 avidemux3_qt4

I assume there are several threads to speed up video encoding and one of them is encoding audio. Another one takes over control of the multiple threads, possibly. Maybe there is something wrong with the communication between the threads while using libx264 functions so one of the slow CPU usage threads is slowing down everything.
BTW, I noticed the GUI to be not very responsive when performance drops, e.g. it'll take several seconds until the abort click is recognized while it will prompt immediately for confirmation when performance is at its expected level.

I attached the project file. Let me know if I shall provide more information or log files.


Thanks
Markus

[mulder77]

Another addendum:

I re-run some tests, this time there was the behaviour that it slowed down after 30 seconds.

[mulder77]

Ha!
Finally some progress...

I run another test, but this time I am not storing the file to my regular file system but to /tmp which is mounted as a tmpfs, so stored in RAM.

No breakdown in performance!

Funny thing is that I can't notice any problems with my disk performance.

Code Select Expand


# hdparm -t /dev/md5

/dev/md5:
Timing buffered disk reads: 974 MB in  3.01 seconds = 323.27 MB/sec

$ dd if=/dev/zero of=/daten/test bs=1M count=4096
4096+0 records in
4096+0 records out
4294967296 bytes (4.3 GB) copied, 20.9564 s, 205 MB/s

[Jan Gruuthuse]

Ok situation here:
Output: sda1 (wdc wd1002faex)

Code Select Expand

sudo hdparm -t /dev/sda1

/dev/sda1:
Timing buffered disk reads: 392 MB in  3.01 seconds = 130.10 MB/sec

Input  : sdb1 (wd15EARS)

Code Select Expand

sudo hdparm -t /dev/sdb1

/dev/sdb1:
Timing buffered disk reads: 246 MB in  3.02 seconds =  81.57 MB/sec

reading drive sdb1 writting to sda1

Code Select Expand

dd if=/media/DataB_SATA3/ndrHD.ts of=/home/jan/Videos/test.ts bs=1M count=4096

4096+0 records in
4096+0 records out
4294967296 bytes (4,3 GB) copied, 31,8957 s, 135 MB/s

[Jan Gruuthuse]

processed in around 52 seconds and fluctuating between 30 to 42 FPS

top - 07:12:56 up 57 min,  3 users,  load average: 2.20, 1.74, 0.95
Tasks: 165 total,   2 running, 163 sleeping,   0 stopped,   0 zombie
Cpu(s): 12.9%us,  1.9%sy, 78.6%ni,  6.4%id,  0.0%wa,  0.0%hi,  0.2%si,  0.0%st
Mem:  16397492k total, 10651444k used,  5746048k free,   201732k buffers
Swap:        0k total,        0k used,        0k free,  9215360k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                           
31261 jan       20   0 1983m 221m  57m S  369  1.4   7:21.78 avidemux3_qt4                                                     
1955 jan       20   0  646m 3888 2712 S    1  0.0   0:53.64 conky                                                             
1283 root      20   0  160m  56m  31m S    0  0.4   1:05.12 Xorg                                                             
1579 jan       20   0  575m  17m  11m S    0  0.1   0:00.61 gnome-terminal                                                   
1656 jan       20   0  653m  16m  11m S    0  0.1   0:06.22 metacity                                                         
28286 root      20   0     0    0    0 S    0  0.0   0:00.31 kworker/0:1                                                       
    1 root      20   0 24528 2472 1352 S    0  0.0   0:00.68 init                                                             
    2 root      20   0     0    0    0 S    0  0.0   0:00.00 kthreadd                                                         
    3 root      20   0     0    0    0 S    0  0.0   0:00.10 ksoftirqd/0                                                       
    5 root      20   0     0    0    0 S    0  0.0   0:00.16 kworker/u:0                                                       
    6 root      RT   0     0    0    0 S    0  0.0   0:00.00 migration/0                                                       
    7 root      RT   0     0    0    0 S    0  0.0   0:00.00 watchdog/0                                                       
    8 root      RT   0     0    0    0 S    0  0.0   0:00.00 migration/1                                                       
    9 root      20   0     0    0    0 S    0  0.0   0:00.00 kworker/1:0                                                       
   10 root      20   0     0    0    0 S    0  0.0   0:00.07 ksoftirqd/1                                                       
   12 root      RT   0     0    0    0 S    0  0.0   0:00.00 watchdog/1                                                       
   13 root      RT   0     0    0    0 S    0  0.0   0:00.00 migration/2                                                       

[Jan Gruuthuse]

Top with key press H shows also 8 threads here, is no issue then.
I've now made a desktop recording of the test running, it is slower due to the recording.
Keep also an eye on conky running on the top right.
Bottleneck most likely your hard disk i/o? Running in out from same hard disk? not enough space to work the lot? my guess would be size needed  = size of file times 3?
Recorded Test (16 MB): AvidemuxTest.mp4

Anything else I could do, let me know. Let us know if issue is solved.

[mulder77]

I assume this is far more complicated then just an I/O bottleneck.
Take a look at the vmstat during a slow encoding:

Code Select Expand

$ vmstat 1
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
7  0      0 157584 413708 13947896    0    0    80   138  191  308  2  5 92  1  0
3  0      0 157088 413716 13948052    0    0     0    44 6853 4562 77  4 18  1  0
3  0      0 156840 413716 13948184    0    0     0     0 6716 4376 77  5 18  0  0
3  0      0 156716 413716 13948344    0    0     0     0 6543 3890 79  5 16  0  0
5  0      0 156592 413716 13948440    0    0     0     0 6864 4503 81  4 16  0  0
6  0      0 156468 413716 13948536    0    0     0  5140 6972 4434 80  5 15  0  0
4  0      0 156476 413724 13948560    0    0     0    40 7073 4481 79  5 16  0  0
3  0      0 156352 413724 13948720    0    0     0    16 6639 4349 74  4 22  0  0
2  0      0 156104 413724 13948848    0    0     0     0 6269 4109 69  4 27  0  0
2  0      0 155492 413724 13948976    0    0     0     0 5962 3625 71  6 23  0  0
8  0      0 155236 413724 13949072    0    0     0    36 7314 5232 80  6 14  0  0
3  0      0 154988 413724 13949136    0    0     0     0 7628 6227 83  5 13  0  0
3  0      0 154988 413732 13949160    0    0     0    44 6826 5803 75  5 20  0  0
3  0      0 154864 413732 13949264    0    0     0     0 6910 5214 80  5 14  0  0
2  0      0 154740 413732 13949392    0    0     0     0 7344 6132 79  4 17  0  0
6  0      0 154616 413732 13949456    0    0     0    52 7063 6193 70  5 25  0  0
7  0      0 154616 413732 13949520    0    0     0     0 7874 6354 81  5 14  0  0
6  0      0 154368 413748 13949664    0    0     0   128 7512 5910 80  5 14  1  0
4  0      0 154368 413748 13949776    0    0     0     0 7983 5961 91  5  4  0  0
4  0      0 154368 413748 13949872    0    0     0     0 7555 5426 90  6  5  0  0
4  0      0 155228 413748 13950000    0    0     0     0 7227 3867 90  6  4  0  0
4  0      0 154864 413748 13950192    0    0     0     0 7918 4940 91  5  4  0  0
6  0      0 154616 413756 13950312    0    0     0    28 8327 4777 94  4  2  0  0
5  0      0 154492 413756 13950480    0    0     0    16 7949 4929 95  5  0  0  0
4  0      0 154244 413756 13950608    0    0     0     0 7926 4755 94  5  1  0  0
5  0      0 154120 413756 13950708    0    0     0     0 7044 4569 85  5 11  0  0
5  0      0 154120 413756 13950740    0    0     0   548 7913 5010 93  5  2  0  0
4  0      0 154012 413764 13950796    0    0     0    44 7581 4942 95  5  0  0  0
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
5  0      0 154012 413764 13950868    0    0     0    16 7483 4490 92  5  4  0  0
4  0      0 154384 413764 13950932    0    0     0     0 7437 3637 93  6  2  0  0
5  0      0 154012 413764 13950996    0    0     0     0 6725 2558 90  5  5  0  0
5  0      0 153888 413764 13951188    0    0     0     0 7073 2969 97  4  0  0  0
4  0      0 153764 413764 13951316    0    0     0     0 7218 2916 95  4  1  0  0
3  0      0 153640 413772 13951444    0    0     0    44 7391 2923 94  4  2  0  0
6  0      0 153152 413772 13951572    0    0     0     0 7325 3134 87  4  9  0  0
4  0      0 153020 413772 13951764    0    0     0     0 7814 3050 91  4  5  0  0
5  0      0 153020 413772 13951828    0    0     0     0 16689 3073 80 13  7  0  0
4  0      0 152212 413772 13951860    0    0     0     0 8127 3179 95  5  0  0  0
4  0      0 152336 413788 13951912    0    0     0   112 7317 3298 94  4  1  2  0
4  0      0 170068 413764 13933984    0    0     0     0 7481 3268 95  4  1  0  0
5  0      0 171184 413764 13933948    0    0     0  3600 7249 3295 94  4  1  0  0
4  0      0 170936 413764 13934012    0    0     0     0 8100 3737 94  5  1  0  0
5  0      0 170936 413764 13934140    0    0     0     0 8127 3847 94  4  2  0  0
5  0      0 170812 413772 13934196    0    0     0    56 8233 4039 92  5  4  0  0
4  0      0 170812 413772 13934356    0    0     0     0 7895 3935 89  4  7  0  0
5  0      0 170812 413772 13934388    0    0     0     0 8563 4243 95  5  1  0  0
3  0      0 170812 413772 13934452    0    0     0     0 8150 4265 90  4  5  0  0
5  0      0 170060 413772 13934484    0    0     0     0 8010 3951 88  4  7  0  0

You'll see hardly no disk activity at all, and where should this demand come from? Let's assume 2000 kbit/s with 5 FPS, this results in 400 kbit/s disk write activity. So we talk about 50 KiB/s.

If I/O would be an issue, I would expect top/vmstat to show significant wait times in %. In the above vmstat sample it's the second most right column. It's nearly flat at 0%.

I did some tests in the filesystem with dd, read and write on the same device, just like my encoding setup:

Code Select Expand

$ dd if=/daten/aufnahmen/HD/Super\ RTL\ HD-Disney\ Phineas\ und\ Ferb.2012-08-13.19-20.mkv of=test bs=1M
1631+1 records in
1631+1 records out
1711265068 bytes (1.7 GB) copied, 20.7652 s, 82.4 MB/s

Here is the corresponding output of vmstat during this dd activity:

Code Select Expand

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
1  1      0 226760 414232 13818624    0    0    79   144  210    2  3  5 91  1  0
0  1      0 227080 414232 13818624    0    0     0 153088 4666 13283  0 11 67 22  0
2  1      0 227012 414232 13818624    0    0     0 168704 4362 14575  0 12 64 24  0
0  1      0 226612 414232 13818624    0    0     0 192000 4535 17465  0 13 64 23  0
0  2      0 226772 414236 13818620    0    0     0 89156 3727 9647  0  9 66 25  0
4  1      0 228212 414256 13818680    0    0     4 14004 7939 5599 87  6  6  2  0
4  0      0 228212 414256 13818720    0    0     0    16 7939 4809 96  5  0  0  0
5  0      0 228212 414256 13818752    0    0     0     0 7948 4798 95  5  0  0  0
6  0      0 228088 414256 13818784    0    0     0     0 7548 4534 92  5  3  0  0
6  0      0 228584 414256 13818880    0    0     0     0 7994 4477 95  5  0  0  0
6  0      0 228212 414264 13818936    0    0     0    60 7579 4411 94  6  0  0  0
7  0      0 227668 414264 13819008    0    0     0     0 7500 4841 95  6  0  0  0
5  0      0 228096 414264 13819008    0    0     0     0 7483 4343 95  5  0  0  0
5  0      0 228096 414264 13819068    0    0     0     0 7718 4053 96  4  0  0  0
5  0      0 228096 414264 13819132    0    0     0     0 7942 3938 95  5  0  0  0
7  0      0 228096 414264 13819164    0    0     0     0 7685 3992 95  4  0  0  0
5  0      0 228104 414272 13819188    0    0     0    44 7743 4066 95  5  0  0  0
2  0      0 228104 414272 13819260    0    0     0     0 7736 3822 96  4  1  0  0
7  0      0 227732 414272 13819360    0    0     0     0 7014 2927 94  5  1  0  0
3  1      0 1844204 414276 12211620    0    0     4     0 7179 3723 88 12  0  1  0
6  1      0 1299248 414276 12757344    0    0 284672     0 8374 3767 86  9  3  3  0
6  2      0 827620 414288 13228480    0    0 233472   164 8600 4302 90 10  0  0  0
5  1      0 389032 414288 13667596    0    0 221184    36 8218 4278 91 10  0  0  0
5  1      0 188616 414288 13867492    0    0 98304 51488 9858 7609 91  9  0  0  0
6  1      0 158468 412764 13901172    0    0 73728 55568 9683 8043 87  9  1  3  0
4  1      0 170000 411160 13892684    0    0 73728 44520 9896 8040 91  8  0  0  0
6  0      0 188336 409292 13895920    0    0 73728 29556 9426 6739 92  8  0  0  0
7  2      0 167524 399092 13929736    0    0 98304 35600 10573 9435 90 10  0  0  0
5  2      0 169068 384132 13947232    0    0 147456 47160 8563 6160 90 10  0  0  0
5  1      0 169700 382728 13949700    0    0 86016 40132 11258 6228 87  9  0  3  0
7  1      0 172268 382688 13952000    0    0 147456 24320 11088 4454 89 11  0  0  0
3  1      0 158992 382396 13967012    0    0 122880 43728 8145 4847 87 10  0  3  0
4  2      0 174028 382104 13954304    0    0 10232 42072 9479 8867 89 11  0  1  0
0  1      0 166136 382104 13962392    0    0     0 215056 6692 38993 19 13 36 32  0
1  1      0 166456 382104 13962392    0    0     0 215552 4731 17655  0 15 62 23  0
0  1      0 166212 382104 13962392    0    0     0 205056 4604 17966  1 13 64 23  0
0  1      0 166424 382104 13962392    0    0     0 162816 4316 13360  0 11 65 23  0
0  1      0 166048 382104 13962392    0    0     0 154880 4273 13387  0 12 65 23  0
1  1      0 166104 382104 13962392    0    0     0 161280 4321 12551  0 12 65 23  0
0  1      0 165840 382104 13962392    0    0     0 41748 3515 5515  0  7 70 23  0
4  3      0 166376 382108 13962388    0    0    76 103568 4284 11967  5 10 59 27  0
5  0      0 157260 382116 13962964    0    0   424   152 8338 5457 94  6  0  0  0
6  0      0 166344 382116 13962956    0    0     0    20 7652 4903 89  4  7  0  0
5  0      0 166344 382116 13963084    0    0     0    16 7955 4650 95  5  0  0  0
6  0      0 166344 382116 13963116    0    0     0     0 8135 4848 95  4  1  0  0

So as long as we're talking about basic I/O operations on this system, it's operating totally fine, having many multiple capacities of what such encoding would need.
What I will do next is to create a flat file on the device and create a new ext4 filesystem in it, mounting it via loop.

[mean]

You can also try using the dummy muxer, it writes nothing to disk

[mulder77]

Sigh..
Another test to my tmpfs shows poor performance now. Can't tell you why it was better yesterday evening.

Now I using the dummy muxer, still slow performance.
So sorry for heading into the wrong direction, but I/O is out of scope, I guess.

[mulder77]

I uploaded a screencast here:

https://www.hidrive.strato.com/lnk/hdyvolnK

Currently I am out of ideas...