Steps to replicate the issue (include links if applicable):
- install MW1. 39
- install TMH
- upload a mp4 file or click on "reset transcode"
What happens?:
Immediately, a ffmpeg encoding is started via the PHP-fpm web process.
What should have happened instead?:
The transcoding should have been deferred to a runJobs.php --type webVideoTranscode cron job.
runJobs.php (without --type) and runJobs.php --type webVideoTranscode would start enconding jobs sometimes, but usually it simply says "Job queue is empty". Perhaps that is a concurrency issue?
Software version (skip for WMF-hosted wikis like Wikipedia):
MediaWiki 1.39.3
PHP 8.1.16 (fpm-fcgi)
MariaDB 10.6.14-MariaDB-log
ICU 73.1
Pygments 2.11.2
TimedMediaHandler 0.6.0 (4d734d8)
Other information (browser name/version, screenshots, etc.):
MW debug.log from when "Reset transcoding" is pressed. Cron is disabled, so no background job should have been started.
Sample page with mp4 file: https://wikidev.tnonline.net/w/File:20230607_154618.mp4
Localsettings.php
wfLoadExtension( 'TimedMediaHandler' ); $wgFFmpegLocation = '/usr/bin/ffmpeg'; $wgTmhEnableMp4Uploads = true; $wgTmhEnableMp3Uploads = true; $wgEnableTranscode = true; $wgFFmpegVP9RowMT = true; $wgEnableNiceBackgroundTranscodeJobs = false; $wgTranscodeBackgroundTimeLimit = 0; $wgMaxShellMemory = 0; $wgMaxShellTime = 0; $wgTranscodeBackgroundTimeLimit = 86400; $wgFFmpegThreads = 4;
debug.log
[objectcache] getWithSetCallback(my_wiki:page-content-model:1515): process cache hit OutputPage::sendCacheControl: private caching (config); Tue, 20 Jun 2023 12:17:41 GMT ** [DBQuery] MediaWiki::restInPeace [0s] localhost: COMMIT [DeferredUpdates] DeferredUpdates::run: started MWCallableUpdate_Pingback::schedulePingback #341 [DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0 [DBQuery] Wikimedia\Rdbms\Database::beginIfImplied (Pingback::wasRecentlySent) [0s] localhost: BEGIN [DBQuery] Pingback::wasRecentlySent [0s] localhost: SELECT ul_value FROM `updatelog` WHERE ul_key = 'Pingback-1.39.3' LIMIT 1 [DBQuery] Pingback::schedulePingback [0s] localhost: COMMIT [DeferredUpdates] DeferredUpdates::run: ended MWCallableUpdate_Pingback::schedulePingback #341, processing time: 0.00043606758117676 [DeferredUpdates] DeferredUpdates::run: started MWCallableUpdate_MediumSpecificBagOStuff->trackDuplicateKeys #789 [objectcache] Duplicate get(): "my_wiki:pcache:idoptions:223" fetched 2 times [DeferredUpdates] DeferredUpdates::run: ended MWCallableUpdate_MediumSpecificBagOStuff->trackDuplicateKeys #789, processing time: 7.2002410888672E-5 [DeferredUpdates] DeferredUpdates::run: started TransactionRoundDefiningUpdate_MediaWiki::schedulePostSendJobs #903 [objectcache] getWithSetCallback(global:rdbms-server-readonly:localhost:my_wiki:): process cache hit [runJobs] webVideoTranscodePrioritized File:20230607_154618.mp4 transcodeMode=derivative transcodeKey=120p.vp9.webm prioritized=1 namespace=6 title=20230607_154618.mp4 requestId=673bd2a33155f3d5b49e4cc2 (uuid=6ff7d72f395545248f83bd60f788af6f,timestamp=1687263461) STARTING [WebVideoTranscodeJob] Encoding to codec: vp9 [DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0 [DBQuery] Wikimedia\Rdbms\Database::beginIfImplied (MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscodeJob::run) [0s] localhost: BEGIN [DBQuery] MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscodeJob::run [0s] localhost: SELECT transcode_time_startwork FROM `transcode` WHERE transcode_image_name = '20230607_154618.mp4' AND transcode_key = '120p.vp9.webm' LIMIT 1 [DBQuery] MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscodeJob::run [0s] localhost: UPDATE `transcode` SET transcode_time_startwork = '20230620121742' WHERE transcode_image_name = '20230607_154618.mp4' AND transcode_key = '120p.vp9.webm' [DBQuery] Wikimedia\Rdbms\Database::ping [0s] localhost: SELECT 1 AS ping [DBQuery] MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscodeJob::run [0.001s] localhost: COMMIT [objectcache] RedisBagOStuff debug: get(WANCache:global:filerepo-file:my_wiki:db16e6d180b3d0f5f5f8e05365baff43aa688a38|#|v) on /tmp/redis.sock: success [WebVideoTranscodeJob] Running cmd: '/usr/bin/ffmpeg' -hwaccel auto -nostdin -y -i '/var/www/domains/wikidev.tnonline.net/htdocs/mediawiki/images/d/d1/20230607_154618.mp4' -threads 4 -row-mt 1 -pix_fmt yuv420p10 -crf '35' -qmin '8' -qmax '51' -vb '120000' -vcodec libvpx-vp9 -auto-alt-ref 1 -lag-in-frames 25 -g '240' -speed 4 -f webm -s 214x120 -max_muxing_queue_size 1024 -an -pass '1' -passlogfile '/tmp/transcode_120p.vp9.webm70c63629c042.webm.log' /dev/null [exec] Executing: /bin/bash '/var/www/domains/wikidev.tnonline.net/htdocs/mediawiki/vendor/wikimedia/shellbox/src/Command/limit.sh' ''\''/usr/bin/ffmpeg'\'' -hwaccel auto -nostdin -y -i '\''/var/www/domains/wikidev.tnonline.net/htdocs/mediawiki/images/d/d1/20230607_154618.mp4'\'' -threads 4 -row-mt 1 -pix_fmt yuv420p10 -crf '\''35'\'' -qmin '\''8'\'' -qmax '\''51'\'' -vb '\''120000'\'' -vcodec libvpx-vp9 -auto-alt-ref 1 -lag-in-frames 25 -g '\''240'\'' -speed 4 -f webm -s 214x120 -max_muxing_queue_size 1024 -an -pass '\''1'\'' -passlogfile '\''/tmp/transcode_120p.vp9.webm70c63629c042.webm.log'\'' /dev/null 2>&1' 'SB_INCLUDE_STDERR=;SB_CPU_LIMIT=84600; SB_CGROUP='\'''\''; SB_MEM_LIMIT=2147483648; SB_FILE_SIZE_LIMIT=3221225472; SB_WALL_CLOCK_LIMIT=84600; SB_USE_LOG_PIPE=yes' [WebVideoTranscodeJob] Running cmd: '/usr/bin/ffmpeg' -hwaccel auto -nostdin -y -i '/var/www/domains/wikidev.tnonline.net/htdocs/mediawiki/images/d/d1/20230607_154618.mp4' -threads 4 -row-mt 1 -pix_fmt yuv420p10 -crf '35' -qmin '8' -qmax '51' -vb '120000' -vcodec libvpx-vp9 -auto-alt-ref 1 -lag-in-frames 25 -g '240' -speed '2' -f webm -s 214x120 -max_muxing_queue_size 1024 -ab 96000 -ar '48000' -acodec 'libopus' -pass '2' -passlogfile '/tmp/transcode_120p.vp9.webm70c63629c042.webm.log' '/tmp/transcode_120p.vp9.webm70c63629c042.webm' [exec] Executing: /bin/bash '/var/www/domains/wikidev.tnonline.net/htdocs/mediawiki/vendor/wikimedia/shellbox/src/Command/limit.sh' ''\''/usr/bin/ffmpeg'\'' -hwaccel auto -nostdin -y -i '\''/var/www/domains/wikidev.tnonline.net/htdocs/mediawiki/images/d/d1/20230607_154618.mp4'\'' -threads 4 -row-mt 1 -pix_fmt yuv420p10 -crf '\''35'\'' -qmin '\''8'\'' -qmax '\''51'\'' -vb '\''120000'\'' -vcodec libvpx-vp9 -auto-alt-ref 1 -lag-in-frames 25 -g '\''240'\'' -speed '\''2'\'' -f webm -s 214x120 -max_muxing_queue_size 1024 -ab 96000 -ar '\''48000'\'' -acodec '\''libopus'\'' -pass '\''2'\'' -passlogfile '\''/tmp/transcode_120p.vp9.webm70c63629c042.webm.log'\'' '\''/tmp/transcode_120p.vp9.webm70c63629c042.webm'\'' 2>&1' 'SB_INCLUDE_STDERR=;SB_CPU_LIMIT=84600; SB_CGROUP='\'''\''; SB_MEM_LIMIT=2147483648; SB_FILE_SIZE_LIMIT=3221225472; SB_WALL_CLOCK_LIMIT=84600; SB_USE_LOG_PIPE=yes' [DBQuery] Wikimedia\Rdbms\DatabaseMysqlBase::open [0s] localhost: SET group_concat_max_len = 262144, `sql_mode` = '' [DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: opened new connection for local/0 [DBQuery] Wikimedia\Rdbms\DatabaseMysqlBase::serverIsReadOnly [0s] localhost: SELECT @@GLOBAL.read_only AS Value [DBQuery] Wikimedia\Rdbms\Database::beginIfImplied (MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscodeJob::run) [0s] localhost: BEGIN [DBQuery] MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscodeJob::run [0s] localhost: SELECT transcode_time_startwork FROM `transcode` WHERE transcode_image_name = '20230607_154618.mp4' AND transcode_key = '120p.vp9.webm' LIMIT 1 [DBQuery] MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscodeJob::run [0s] localhost: COMMIT [DBQuery] Wikimedia\Rdbms\DatabaseMysqlBase::open [0s] localhost: SET group_concat_max_len = 262144, `sql_mode` = '' [DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: opened new connection for local/0 [DBQuery] Wikimedia\Rdbms\Database::beginIfImplied (MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscodeJob::run) [0s] localhost: BEGIN [DBQuery] MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscodeJob::run [0s] localhost: UPDATE `transcode` SET transcode_error = '',transcode_time_error = NULL,transcode_time_success = '20230620121848',transcode_final_bitrate = '208808' WHERE transcode_image_name = '20230607_154618.mp4' AND transcode_key = '120p.vp9.webm' [DBQuery] MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscodeJob::run [0.002s] localhost: COMMIT WebVideoTranscode:: Invalidate pages that include: 20230607_154618.mp4 [objectcache] RedisBagOStuff debug: get(WANCache:global:rdbms-server-readonly:localhost:my_wiki:|#|v) on /tmp/redis.sock: success [objectcache] RedisBagOStuff debug: add(WANCache:global:rdbms-server-readonly:localhost:my_wiki:|#|m) on /tmp/redis.sock: failure [DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0 [DBQuery] Wikimedia\Rdbms\DatabaseMysqlBase::serverIsReadOnly [0s] localhost: SELECT @@GLOBAL.read_only AS Value [objectcache] RedisBagOStuff debug: add(WANCache:global:rdbms-server-readonly:localhost:my_wiki:|#|v) on /tmp/redis.sock: failure [objectcache] RedisBagOStuff debug: expireAt(WANCache:global:rdbms-server-readonly:localhost:my_wiki:|#|m) on /tmp/redis.sock: failure [objectcache] fetchOrRegenerate(global:rdbms-server-readonly:localhost:my_wiki:): miss, new value computed [DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0 [DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0 [DBQuery] Wikimedia\Rdbms\Database::beginIfImplied (MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscode::invalidatePagesWithFile) [0s] localhost: BEGIN [DBQuery] MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscode::invalidatePagesWithFile [0s] localhost: SELECT page_namespace,page_title FROM `imagelinks`,`page` WHERE il_to = '20230607_154618.mp4' AND (il_from = page_id) LIMIT 501 [objectcache] getWithSetCallback(global:rdbms-server-readonly:localhost:my_wiki:): process cache hit [DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0 [squid] CdnCacheUpdate::purge: /mediawiki/images/transcoded/d/d1/20230607_154618.mp4/20230607_154618.mp4.120p.vp9.webm [DBQuery] MediaWiki\TimedMediaHandler\WebVideoTranscode\WebVideoTranscodeJob::run [0s] localhost: COMMIT [DeferredUpdates] DeferredUpdates::run: started AutoCommitUpdate_Title::invalidateCache #1068 [DBQuery] Title::invalidateCache [0.002s] localhost: UPDATE `page` SET page_touched = '20230620121848' WHERE page_namespace = 6 AND page_title = '20230607_154618.mp4' AND (page_touched < '20230620121848') [objectcache] RedisBagOStuff debug: set(WANCache:my_wiki:page:6:db16e6d180b3d0f5f5f8e05365baff43aa688a38|#|v) on /tmp/redis.sock: success [DeferredUpdates] DeferredUpdates::run: ended AutoCommitUpdate_Title::invalidateCache #1068, processing time: 0.001978874206543 [DeferredUpdates] DeferredUpdates::run: started AutoCommitUpdate_Title::invalidateCache #1129 [DBQuery] Title::invalidateCache [0.002s] localhost: UPDATE `page` SET page_touched = '20230620121848' WHERE page_namespace = 0 AND page_title = 'Draft/videotest' AND (page_touched < '20230620121848') [DeferredUpdates] DeferredUpdates::run: ended AutoCommitUpdate_Title::invalidateCache #1129, processing time: 0.0020020008087158 [runJobs] webVideoTranscodePrioritized File:20230607_154618.mp4 transcodeMode=derivative transcodeKey=120p.vp9.webm prioritized=1 namespace=6 title=20230607_154618.mp4 requestId=673bd2a33155f3d5b49e4cc2 (uuid=6ff7d72f395545248f83bd60f788af6f,timestamp=1687263461) t=66137 good [DeferredUpdates] DeferredUpdates::run: ended TransactionRoundDefiningUpdate_MediaWiki::schedulePostSendJobs #903, processing time: 66.138623952866 [DeferredUpdates] DeferredUpdates::run: started MWCallableUpdate_WANObjectCache->scheduleAsyncRefresh #833 [objectcache] RedisBagOStuff debug: get(WANCache:my_wiki:messages-big:f6c4f725a607bfe8fa0cf0c05ee4f470:Tooltip-p-notifications/en|#|v) on /tmp/redis.sock: success [DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0 [objectcache] RedisBagOStuff debug: get(WANCache:my_wiki:page:8:73efbe170fc384b4040efc0fc9d960a8ff65f4fb|#|v) on /tmp/redis.sock: success [DBConnection] Wikimedia\Rdbms\LoadBalancer::getLocalConnection: reused a connection for local/0 [DBQuery] Wikimedia\Rdbms\Database::beginIfImplied (MediaWiki\Page\PageStore::getPageByNameViaLinkCache) [0s] localhost: BEGIN [DBQuery] MediaWiki\Page\PageStore::getPageByNameViaLinkCache [0s] localhost: SELECT page_id,page_namespace,page_title,page_is_redirect,page_is_new,page_touched,page_links_updated,page_latest,page_len,page_content_model FROM `page` WHERE page_namespace = 8 AND page_title = 'Tooltip-p-notifications/en' LIMIT 1 [objectcache] fetchOrRegenerate(my_wiki:page:8:73efbe170fc384b4040efc0fc9d960a8ff65f4fb): miss, new value computed [objectcache] RedisBagOStuff debug: get(WANCache:my_wiki:messages-big:f6c4f725a607bfe8fa0cf0c05ee4f470:Tooltip-p-notifications/en|#|v) on /tmp/redis.sock: success [objectcache] RedisBagOStuff debug: add(WANCache:my_wiki:messages-big:f6c4f725a607bfe8fa0cf0c05ee4f470:Tooltip-p-notifications/en|#|v:lock) on /tmp/redis.sock: failure [objectcache] RedisBagOStuff debug: get(WANCache:my_wiki:messages-big:f6c4f725a607bfe8fa0cf0c05ee4f470:Tooltip-p-notifications/en|#|v) on /tmp/redis.sock: success [objectcache] RedisBagOStuff debug: set(WANCache:my_wiki:messages-big:f6c4f725a607bfe8fa0cf0c05ee4f470:Tooltip-p-notifications/en|#|v) on /tmp/redis.sock: success [objectcache] RedisBagOStuff debug: delete(WANCache:my_wiki:messages-big:f6c4f725a607bfe8fa0cf0c05ee4f470:Tooltip-p-notifications/en|#|v:lock) on /tmp/redis.sock: success [objectcache] fetchOrRegenerate(my_wiki:messages-big:f6c4f725a607bfe8fa0cf0c05ee4f470:Tooltip-p-notifications/en): renew, new value computed [DBQuery] WANObjectCache->scheduleAsyncRefresh [0s] localhost: COMMIT [DeferredUpdates] DeferredUpdates::run: ended MWCallableUpdate_WANObjectCache->scheduleAsyncRefresh #833, processing time: 0.0024659633636475 [DeferredUpdates] DeferredUpdates::run: started JobQueueEnqueueUpdate #1099 [DeferredUpdates] DeferredUpdates::run: ended JobQueueEnqueueUpdate #1099, processing time: 6.1988830566406E-5 [DBReplication] LBFactory shutdown completed Request ended normally [session] Saving all sessions on shutdown
Another issue is that second pass -pass 2 never gets executed if $wgEnableNiceBackgroundTranscodeJobs=true;
