Changing AsyncDepth returns error when synchronizing

[HermanMolinder]

I have an application using DEC1->VPP1->VPP2. DEC1 and VPP1 share session and VPP2 has another session. Synchronization is done at last step. Both sessions are cloned from an "empty" parent session.

When using AsyncDepth=3 or AsyncDepth=0 the application works as expected. But using other values on AsyncDepth (tested 1, 2, 4, 5, 6) the sync operation fails.

I then tried to sync after each async operation and found that syncing after VPP1 returns MFX_ERR_UNKNOWN. When tracing this error status I found that it comes from pTask->opRes in MediaSDK/_studio/mfx_lib/scheduler/src/mfx_scheduler_core_ischeduler.cpp:324.

Is this a bug or am I missing something about the AsyncDepth parameter?

Additional info: -Video memory is used through vaapi. -Tested on Apollolake. -Open source msdk from following commits: libva: b3be72a5a110880f70626d7c3bed953cdde124b2 media-driver: 1c2b0615d749c45c07f9aee6586774816989c5b3 gmmlib: 247673f8e487d62b818876dc1905036e477986c1 MediaSDK: 7c2b069

Here's a gdb print of the pTask object:

(gdb) p pTask $15 = {<mfxDependencyItem<4>> = { = {_vptr.mfxDependencyItemInterface = 0x7ffff32722b8 <vtable for MFX_SCHEDULER_TASK+16>}, m_bStatusOk = true, m_beginListObjects = { pObj = 0x0, pNext = 0x7fffe0063a48, pPrev = 0x0}, m_endListObjects = {pObj = 0x0, pNext = 0x7fffe0063a30, pPrev = 0x7fffe0063a30}, m_dependency = {{pObj = 0x7fffe0063a20, pNext = 0x0, pPrev = 0x0}, {pObj = 0x7fffe0063a20, pNext = 0x0, pPrev = 0x0}, {pObj = 0x7fffe0063a20, pNext = 0x0, pPrev = 0x0}, {pObj = 0x7fffe0063a20, pNext = 0x0, pPrev = 0x0}}}, taskID = 0, jobID = 8, done = {handle = {data = {{wseq = 4, wseq32 = {low = 4, high = 0}}, {g1_start = 2, g1_start32 = {low = 2, high = 0}}, __g_refs = {0, 0}, g_size = {0, 0}, g1_orig_size = 4, wrefs = 0, __g_signals = {0, 0}}, size = "\004\000\000\000\000\000\000\000\002", '\000' <repeats 23 times>, "\004", '\000' <repeats 14 times>, align = 4}, is_valid = 1}, opRes = MFX_ERR_UNKNOWN, curStatus = MFX_ERR_UNKNOWN, param = {task = {pOwner = 0x7fffe0062b20, entryPoint = {pState = 0x7fffe04d8e10, pParam = 0x7fffe0063720, pRoutine = 0x7ffff2c8ee00 <MfxHwVideoProcessing::VideoVPPHW::QueryTaskRoutine(void, void*, unsigned int, unsigned int)>, pCompleteProc = 0x0, pGetSubTaskProc = 0x0, pCompleteSubTaskProc = 0x0, requiredNumThreads = 1, pRoutineName = 0x7ffff2f8d7b4 "VPP Query"}, bObsoleteTask = false, obsolete_params = {{encode = {ctrl = 0x0, surface = 0x0, bs = 0x0, internal_params = { = {Header = {BufferId = 0, BufferSz = 0}, reserved = {0, 0, 0, 0}, reserved1 = 0, MfxNalUnitType = 0, SkipFrame = 0, QP = 0, FrameType = 0, NumExtParam = 0, NumPayload = 0, reserved2 = 0, ExtParam = 0x0, Payload = 0x0}, FrameOrder = 0, InternalFlags = 0, surface = 0x0}}, decode = {bs = 0x0, surface_work = 0x0, surface_out = 0x0}, vpp = {in = 0x0, out = 0x0, aux = 0x0}, enc = {in = 0x0, out = 0x0}, pak_ext = {in = 0x0, out = 0x0}}}, pSrc = {0x7fffe0063720, 0x0, 0x0, 0x0}, pDst = { 0x7fffe04d11c0, 0x7fffefb4fd30, 0x0, 0x7fffe0063a20}, priority = MFX_PRIORITY_NORMAL, threadingPolicy = MFX_TASK_THREADING_INTRA, nTaskId = 805306376, nParentId = 4}, pThreadAssignment = 0x0, occupancy = 0, threadMask = 0, numberOfCalls = 1, bWaiting = false, timing = {timeLastEnter = 1529057930310436, timeLastCallIssued = 1529057930310436, timeLastCallProcessed = 1529057930310436, timeSpent = 3, timeOverhead = 0, hwCounterLastEnter = 0}, sourceInfo = {pFileName = 0x0, lineNumber = 0}, dependencies = {dstIdx = {2, 3, 0, 4}}}, pNext = 0x0, m_pSchedulerCore = 0x6ce0b0}

[artem-shaporenko]

Hi @HermanMolinder, what are vpp filters enabled for failing vpp call? pTask->opRes in scheduler is recorded status from vpp asynchronous part, most likely something wrong happened during VPP operation.

[HermanMolinder]

Hi @artem-shaporenko

No filters are used, so it should just be a passthrough. Here are the input and output frame info (No ExtParam is used):

(gdb) p session->processor.mfxPar.vpp.In $8 = {reserved = {0, 0, 0, 0}, reserved4 = 0, BitDepthLuma = 0, BitDepthChroma = 0, Shift = 0, FrameId = {TemporalId = 0, PriorityId = 0, {{DependencyId = 0, QualityId = 0}, {ViewId = 0}}}, FourCC = 842094158, {{Width = 720, Height = 576, CropX = 0, CropY = 0, CropW = 720, CropH = 576}, {BufferSize = 37749456, reserved5 = 37749456}}, FrameRateExtN = 25, FrameRateExtD = 1, reserved3 = 0, AspectRatioW = 64, AspectRatioH = 45, PicStruct = 0, ChromaFormat = 1, reserved2 = 0}

(gdb) p session->processor.mfxPar.vpp.Out $9 = {reserved = {0, 0, 0, 0}, reserved4 = 0, BitDepthLuma = 0, BitDepthChroma = 0, Shift = 0, FrameId = {TemporalId = 0, PriorityId = 0, {{DependencyId = 0, QualityId = 0}, {ViewId = 0}}}, FourCC = 842094158, {{Width = 720, Height = 576, CropX = 0, CropY = 0, CropW = 720, CropH = 576}, {BufferSize = 37749456, reserved5 = 37749456}}, FrameRateExtN = 25, FrameRateExtD = 1, reserved3 = 0, AspectRatioW = 64, AspectRatioH = 45, PicStruct = 0, ChromaFormat = 1, reserved2 = 0}

[HermanMolinder]

This is very interesting. I tried to apply some filters and suddenly it works (tested with AsyncDepth=2).

Filters used are resizing and frame rate conversion.

(gdb) p session->processor.mfxPar.vpp.In $1 = {reserved = {0, 0, 0, 0}, reserved4 = 0, BitDepthLuma = 0, BitDepthChroma = 0, Shift = 0, FrameId = {TemporalId = 0, PriorityId = 0, {{DependencyId = 0, QualityId = 0}, {ViewId = 0}}}, FourCC = 842094158, {{Width = 720, Height = 576, CropX = 0, CropY = 0, CropW = 720, CropH = 576}, {BufferSize = 37749456, reserved5 = 37749456}}, FrameRateExtN = 25, FrameRateExtD = 1, reserved3 = 0, AspectRatioW = 64, AspectRatioH = 45, PicStruct = 0, ChromaFormat = 1, reserved2 = 0}

(gdb) p session->processor.mfxPar.vpp.Out $2 = {reserved = {0, 0, 0, 0}, reserved4 = 0, BitDepthLuma = 0, BitDepthChroma = 0, Shift = 0, FrameId = {TemporalId = 0, PriorityId = 0, {{DependencyId = 0, QualityId = 0}, {ViewId = 0}}}, FourCC = 842094158, {{Width = 720, Height = 480, CropX = 0, CropY = 0, CropW = 720, CropH = 480}, {BufferSize = 31458000, reserved5 = 31458000}}, FrameRateExtN = 30000, FrameRateExtD = 1001, reserved3 = 0, AspectRatioW = 64, AspectRatioH = 45, PicStruct = 0, ChromaFormat = 1, reserved2 = 0}

(gdb) p (mfxExtVPPFrameRateConversion )session->processor.mfxPar.ExtParam[0] $6 = {Header = {BufferId = 541282886, BufferSz = 72}, Algorithm = 2, reserved = 0, reserved2 = {0 <repeats 15 times>}}

[artem-shaporenko]

Yes, looks like there is a bug in Pass through mode, we'll take a look.

[HermanMolinder]

Thanks! Looking forward to a solution.

[HermanMolinder]

I noticed that this issue only seems to be present if I use passthrough in both VPP1 and VPP2. If I'm using passthough in VPP1 and composite in VPP2 it seems to work as expected.

[dmitryermilov]

Hi @HermanMolinder,

• Can you please post logs from msdk tracer so that we can see how app is using MSDK api. It will help to replicate the bug on our side.

• Besides, could you try to catch a piece of code where MFX_ERR_UNKNOWN is generated the first time? In order to do that it's worth enabling MSDK internal traces: in https://github.com/Intel-Media-SDK/MediaSDK/blob/62087804a9cd279135fc0956e25532c2ffae93ae/_studio/shared/include/mfx_utils.h#L29 please add "#define MFX_DEBUG_TRACE" and recompile the library. Each MFX_CHECK macro will print debug error message to console.

[HermanMolinder]

Hi @dmitryermilov , I will try to get it done this week, before my vacation. Otherwise I'll have a look at it in in August.

[HermanMolinder]

Hi! Please find the trace prints attached:

msdk_trace_sync_error.txt

[HermanMolinder]

The MFX_ERR_UNKNOWN is generated from mfx_vpp_vaapi.cpp:2251 which is called from mfx_vpp_hw.cpp:4384

Please find the backtrace attached:

msdk_bt_sync_error.txt

[HermanMolinder]

Apparently m_feedbackCache.size() is 0 when it fails.

[dmitryermilov]

Right. Please collect and share msdk traces to move further?

[HermanMolinder]

Hi @dmitryermilov ,

I've been struggling with building msdk tracer. Perhaps you can help me? Which defines and where to put them? Do I need to add/edit any config files? Where do I expect the tracer output? Terminal prints or in a log file?

[dmitryermilov]

libmfx-tracer.so is a part of MSDK close source packages. You can find it in /opt/intel/mediasdk/tools/tracer/. There is a readme file under this path.

[HermanMolinder]

Thanks, Finally I was able to get the traces. The strange thing is when I use libmfx-tracer.so the bug doesn't appear.

mfxtracer_912.log

[dmitryermilov]

This issue is in invalid VPP behavior when m_bCopyPassThroughEnable=true. There is some misalignment in VPP logic: part of VPP code indeed work via "passthrough" mode(surface copy is done by MSDK, not by driver), another part treats a "passthrough" task as a regular driver task and tries to synchronize the task by QueryTaskStatus. Of course this call fails because the task wasn't submitted to the driver.
In fact with the latest version of MSDK in master or mss2018_r2 branch the issue can not occur because "passthrough" mode is disabled on Linux: https://github.com/Intel-Media-SDK/MediaSDK/blob/1ff19baf50063e3be25837c3fd8202dfa4ee0d36/_studio/mfx_lib/vpp/src/mfx_vpp_hw.cpp#L6050

On the other hand, the issue is actual for Windows MSDK project.

My recommendation – please update code to latest MSDK version. Meanwhile we’ll fix the case when config.m_bCopyPassThroughEnable = true to get rid of the issue on Windows.

[HermanMolinder]

Thanks @dmitryermilov,

I'm glad that you found the issue. I will update msdk, so this bug won't be triggered for me.