This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

DRA72XEVM: TI IPC/LAD initilisation error

Part Number: DRA72XEVM

Hi,

We've recently encountered a problem in which we have to add a delay before starting the user space application in order to properly create a message queue.
The platform is DRA71, configured with one A15 core running Linux and one C66 running SYS/BIOS. TI IPC MessageQ is used to communicate. Linux user-space app fails when trying to open the remote messageQ.

It seems that NameServer_attach fails when trying to connect to the socket. Adding 300ms sleep before running this procedure makes it work correctly.
Any ideas what could cause that? Both, working (with 300ms sleep) and not working example (starting immediately) hit (Invalid argument) error but one succeeds on the fourth try while the other one still fails.


Below you'll find LAD logs for when the process fails and for when the process succeeds.

Log, in which app starts OK:

[0.027673]
Initializing LAD... [0.028638] NameServer_setup: entered, refCount=0
[0.028796] NameServer_setup: creating listener thread
[0.029271] NameServer_setup: exiting, refCount=1
[0.029682] NameServer_create(): 'GateMP'
[0.029845]
    opening FIFO: /tmp/LAD/LADCMDS
[0.030129] listener_cb: Entered Listener thread.
[0.030217] NameServer: waiting for unblockFd: 0, and socks: maxfd: 0
[2.484640] Retrieving command...
[2.484702]
LAD_CONNECT:
[2.484713]     client FIFO name = /tmp/LAD/278
[2.484721]     client PID = 278
[2.484729]     assigned client handle = 0
[2.484760]     FIFO /tmp/LAD/278 created
[2.484867]     FIFO /tmp/LAD/278 opened for writing
[2.484906]     sent response
[2.484914] DONE
[2.484921] Retrieving command...
[2.484999] Sending response...
[2.485015] Retrieving command...
[2.485053] LAD_MULTIPROC_GETCONFIG: calling MultiProc_getConfig()...
[2.485067] MultiProc_getConfig() - 5 procs
[2.485075] # processors in cluster: 5
[2.485082] cluster baseId: 0
[2.485089]      ProcId 0 - "HOST"
[2.485096]      ProcId 1 - "IPU2"
[2.485104]      ProcId 2 - "IPU1"
[2.485111]      ProcId 3 - "DSP2"
[2.485118]      ProcId 4 - "DSP1"
[2.485125]     status = 0
[2.485132] DONE
[2.485139] Sending response...
[2.485151] Retrieving command...
[2.485202] LAD_NAMESERVER_SETUP: calling NameServer_setup()...
[2.485211] NameServer_setup: entered, refCount=1
[2.485219] NameServer_setup: already setup
[2.485225] NameServer_setup: exiting, refCount=2
[2.485233]     status = 1
[2.485240] DONE
[2.485246] Sending response...
[2.485258] Retrieving command...
[2.485295] LAD_MESSAGEQ_GETCONFIG: calling MessageQ_getConfig()...
[2.485305]     status = 0
[2.485312] DONE
[2.485319] Sending response...
[2.485331] Retrieving command...
[2.485367] LAD_MESSAGEQ_SETUP: calling MessageQ_setup()...
[2.485377] MessageQ_setup: entered, refCount=0
[2.485385] NameServer_create(): 'MessageQ'
[2.485398] MessageQ_setup: exiting, refCount=1
[2.485406]     status = 0
[2.485413] DONE
[2.485419] Sending response...
[2.485431] Retrieving command...
[2.485634] NameServer_attach: --> procId=1, refCount=0
[2.485662] NameServer_attach: created send socket: 6, procId 1
[2.485692] NameServer_attach: connect failed: procId=1, errno=22 (Invalid argument)
[2.485715]     closing send socket: 6
[2.485739] NameServer_attach: <-- refCount=0, status=-1
[2.485748] Sending response...
[2.485792] Retrieving command...
[2.485809] NameServer_attach: --> procId=2, refCount=0
[2.485824] NameServer_attach: created send socket: 6, procId 2
[2.485835] NameServer_attach: connect failed: procId=2, errno=22 (Invalid argument)
[2.485846]     closing send socket: 6
[2.485862] NameServer_attach: <-- refCount=0, status=-1
[2.485871] Sending response...
[2.485909] Retrieving command...
[2.485924] NameServer_attach: --> procId=3, refCount=0
[2.485938] NameServer_attach: created send socket: 6, procId 3
[2.485949] NameServer_attach: connect failed: procId=3, errno=22 (Invalid argument)
[2.485960]     closing send socket: 6
[2.485976] NameServer_attach: <-- refCount=0, status=-1
[2.485985] Sending response...
[2.486023] Retrieving command...
[2.486038] NameServer_attach: --> procId=4, refCount=0
[2.486051] NameServer_attach: created send socket: 6, procId 4
[2.486077] NameServer_attach: created receive socket: 7, procId 4
[2.487310] NameServer: back from select()
[2.487339] NameServer: listener thread, event: REFRESH
[2.487350] NameServer: waiting for unblockFd: 0, and socks: maxfd: 7
[2.487370] NameServer_attach: <-- refCount=1, status=0
[2.487381] Sending response...
[2.487503] Retrieving command...
[2.487522] LAD_GATEMP_ISSETUP: calling GateMP_isSetup()...
[2.487530]     status = 0
[2.487537] DONE
[2.487544] Sending response...
[2.487578] Retrieving command...
[2.487593] LAD_GATEMP_ATTACH: calling GateMP_attach(4)...
[2.487615] NameServer_getRemote: Sending request via sock: 6
[2.487625] NameServer_getRemote: requesting from procId 4, GateMP: _GateMP_TI_dGate
[2.487656] NameServer_getRemote: pending on waitFd: 1
[2.487759] NameServer: back from select()
[2.487773] NameServer: Listener got NameServer message from sock: 7!
[2.487805] listener_cb: recvfrom socket: fd: 7
[2.487815]      Received ns msg: nbytes: 484, from addr: 61, from vproc: 2
[2.487823] NameServer Reply: instanceName: GateMP, name: _GateMP_TI_dGate, value: 0x770bf
[2.487837] NameServer: waiting for unblockFd: 0, and socks: maxfd: 7
[2.487857] NameServer_getRemote: value for GateMP:_GateMP_TI_dGate not found.
[2.487869] GateMP_attach: failed to open default gate on procId 4
[2.487887]     status = -5
[2.487893] DONE
[2.487900] Sending response...
[2.487934] Retrieving command...
[2.487949] LAD_GATEMP_ISSETUP: calling GateMP_isSetup()...
[2.487956]     status = 0
[2.487963] DONE
[2.487969] Sending response...
[2.488003] Retrieving command...
[2.488018] LAD_GATEHWSPINLOCK_GETCONFIG: calling GateHWSpinlock_getConfig()...
[2.488026] GateHWSpinlock_getConfig()   baseAddr = 0x4a0f6000
[2.488033]      size = 0x1000
        offset = 0x800
[2.488040]     status = 0
[2.488047] DONE
[2.488053] Sending response...
[2.488188] Retrieving command...
[2.488207] LAD_GATEMP_START: calling GateMP_start()...
[2.488215]     status = 0
[2.488222] DONE
[2.488228] Sending response...
[2.488258] Retrieving command...
[2.488272] LAD_GATEMP_GETNUMRESOURCES: calling GateMP_getNumResources()...
[2.488280]     status = 0
[2.488287] DONE
[2.488294] Sending response...
[2.488336] Retrieving command...
[2.488352] LAD_NAMESERVER_GET: calling NameServer_get(0x30228, '_GateMP_TI_dGate'[2.488361] )...
[2.488373] NameServer_getLocal: entry key: '_GateMP_TI_dGate' not found!
[2.488381] NameServer_getRemote: no socket connection to processor 1
[2.488389] NameServer_getRemote: no socket connection to processor 2
[2.488396] NameServer_getRemote: no socket connection to processor 3
[2.488403] NameServer_getRemote: Sending request via sock: 6
[2.488410] NameServer_getRemote: requesting from procId 4, GateMP: _GateMP_TI_dGate
[2.488433] NameServer_getRemote: pending on waitFd: 1
[2.488514] NameServer: back from select()
[2.488526] NameServer: Listener got NameServer message from sock: 7!
[2.488538] listener_cb: recvfrom socket: fd: 7
[2.488546]      Received ns msg: nbytes: 484, from addr: 61, from vproc: 2
[2.488554] NameServer Reply: instanceName: GateMP, name: _GateMP_TI_dGate, value: 0x773d3
[2.488566] NameServer: waiting for unblockFd: 0, and socks: maxfd: 7
[2.488585] NameServer_getRemote: value for GateMP:_GateMP_TI_dGate not found.
[2.488596]     value = 0x10
[2.488603]     status = -5
[2.488610] DONE
[2.488616] Sending response...
[2.488666] Retrieving command...
[2.488681] LAD_MESSAGEQ_CREATE: calling MessageQ_create(0x2f89c, 0x2f8bc)...
[2.488690] MessageQ_create: creating 'HOST:MsgQ:01'
[2.488700] MessageQ_create: returning obj=0x30640, qid=0x80
[2.488708]     status = 0
[2.488715] DONE
[2.488721] Sending response...
[2.489843] Retrieving command...
[2.491290] LAD_MESSAGEQ_ANNOUNCE: calling MessageQ_announce(0x2f89c, 0x30640)...
[2.491309] MessageQ_announce: announcing 0x30640
[2.491323] NameServer_add: Entered key: 'HOST:MsgQ:01', data: 0x80
[2.491333]     status = 0
[2.491340] DONE
[2.491347] Sending response...
[2.491415] Retrieving command...
[2.491432] LAD_NAMESERVER_GETUINT32: calling NameServer_getUInt32(0x30558, 'DSP1:MsgQ:01')...
[2.491443] NameServer_getLocal: entry key: 'DSP1:MsgQ:01' not found!
[2.491453] NameServer_getRemote: no socket connection to processor 1
[2.491460] NameServer_getRemote: no socket connection to processor 2
[2.491467] NameServer_getRemote: no socket connection to processor 3
[2.491474] NameServer_getRemote: Sending request via sock: 6
[2.491481] NameServer_getRemote: requesting from procId 4, MessageQ: DSP1:MsgQ:01
[2.491512] NameServer_getRemote: pending on waitFd: 1
[2.491598] NameServer: back from select()
[2.491610] NameServer: Listener got NameServer message from sock: 7!
[2.491624] listener_cb: recvfrom socket: fd: 7
[2.491633]      Received ns msg: nbytes: 484, from addr: 61, from vproc: 2
[2.491641] NameServer Reply: instanceName: MessageQ, name: DSP1:MsgQ:01, value: 0x40080
[2.491654] NameServer: waiting for unblockFd: 0, and socks: maxfd: 7
[2.491674] NameServer_getRemote: Reply from: 4, MessageQ: name: DSP1:MsgQ:01, value: 0x40080
[2.491698]     value = 0x40080
[2.491706]     status = 0
[2.491713] DONE
[2.491719] Sending response...
[2.491929] Retrieving command...

Log, in which the app fails to start:

[0.955071]
Initializing LAD... [0.955315] NameServer_setup: entered, refCount=0
[0.955341] NameServer_setup: creating listener thread
[0.955456] NameServer_setup: exiting, refCount=1
[0.955538] NameServer_create(): 'GateMP'
[0.955565]
    opening FIFO: /tmp/LAD/LADCMDS
[0.959035] listener_cb: Entered Listener thread.
[0.959129] NameServer: waiting for unblockFd: 0, and socks: maxfd: 0
[-25613773.706787] Retrieving command...
[-25613773.706853]
LAD_CONNECT:
[-25613773.706863]     client FIFO name = /tmp/LAD/302
[-25613773.706872]     client PID = 302
[-25613773.706880]     assigned client handle = 0
[-25613773.706912]     FIFO /tmp/LAD/302 created
[-25613773.707020]     FIFO /tmp/LAD/302 opened for writing
[-25613773.707059]     sent response
[-25613773.707068] DONE
[-25613773.707075] Retrieving command...
[-25613773.707151] Sending response...
[-25613773.707167] Retrieving command...
[-25613773.707206] LAD_MULTIPROC_GETCONFIG: calling MultiProc_getConfig()...
[-25613773.707220] MultiProc_getConfig() - 5 procs
[-25613773.707227] # processors in cluster: 5
[-25613773.707234] cluster baseId: 0
[-25613773.707241]      ProcId 0 - "HOST"
[-25613773.707249]      ProcId 1 - "IPU2"
[-25613773.707256]      ProcId 2 - "IPU1"
[-25613773.707263]      ProcId 3 - "DSP2"
[-25613773.707270]      ProcId 4 - "DSP1"
[-25613773.707277]     status = 0
[-25613773.707284] DONE
[-25613773.707291] Sending response...
[-25613773.707303] Retrieving command...
[-25613773.707354] LAD_NAMESERVER_SETUP: calling NameServer_setup()...
[-25613773.707364] NameServer_setup: entered, refCount=1
[-25613773.707371] NameServer_setup: already setup
[-25613773.707378] NameServer_setup: exiting, refCount=2
[-25613773.707386]     status = 1
[-25613773.707392] DONE
[-25613773.707399] Sending response...
[-25613773.707411] Retrieving command...
[-25613773.707451] LAD_MESSAGEQ_GETCONFIG: calling MessageQ_getConfig()...
[-25613773.707460]     status = 0
[-25613773.707467] DONE
[-25613773.707474] Sending response...
[-25613773.707486] Retrieving command...
[-25613773.707524] LAD_MESSAGEQ_SETUP: calling MessageQ_setup()...
[-25613773.707533] MessageQ_setup: entered, refCount=0
[-25613773.707541] NameServer_create(): 'MessageQ'
[-25613773.707554] MessageQ_setup: exiting, refCount=1
[-25613773.707561]     status = 0
[-25613773.707568] DONE
[-25613773.707575] Sending response...
[-25613773.707587] Retrieving command...
[-25613773.707793] NameServer_attach: --> procId=1, refCount=0
[-25613773.707822] NameServer_attach: created send socket: 6, procId 1
[-25613773.707852] NameServer_attach: connect failed: procId=1, errno=22 (Invalid argument)
[-25613773.707876]     closing send socket: 6
[-25613773.707900] NameServer_attach: <-- refCount=0, status=-1
[-25613773.707910] Sending response...
[-25613773.707952] Retrieving command...
[-25613773.707968] NameServer_attach: --> procId=2, refCount=0
[-25613773.707983] NameServer_attach: created send socket: 6, procId 2
[-25613773.707994] NameServer_attach: connect failed: procId=2, errno=22 (Invalid argument)
[-25613773.708108]     closing send socket: 6
[-25613773.708130] NameServer_attach: <-- refCount=0, status=-1
[-25613773.708139] Sending response...
[-25613773.708181] Retrieving command...
[-25613773.708196] NameServer_attach: --> procId=3, refCount=0
[-25613773.708212] NameServer_attach: created send socket: 6, procId 3
[-25613773.708224] NameServer_attach: connect failed: procId=3, errno=22 (Invalid argument)
[-25613773.708235]     closing send socket: 6
[-25613773.708250] NameServer_attach: <-- refCount=0, status=-1
[-25613773.708259] Sending response...
[-25613773.708297] Retrieving command...
[-25613773.708312] NameServer_attach: --> procId=4, refCount=0
[-25613773.708326] NameServer_attach: created send socket: 6, procId 4
[-25613773.708337] NameServer_attach: connect failed: procId=4, errno=22 (Invalid argument)
[-25613773.708348]     closing send socket: 6
[-25613773.708363] NameServer_attach: <-- refCount=0, status=-1
[-25613773.708372] Sending response...
[-25613773.708413] Retrieving command...
[-25613773.708428] LAD_GATEMP_ISSETUP: calling GateMP_isSetup()...
[-25613773.708451]     status = 0
[-25613773.708459] DONE
[-25613773.708466] Sending response...
[-25613773.708501] Retrieving command...
[-25613773.708516] LAD_GATEHWSPINLOCK_GETCONFIG: calling GateHWSpinlock_getConfig()...
[-25613773.708524] GateHWSpinlock_getConfig()   baseAddr = 0x4a0f6000
[-25613773.708532]      size = 0x1000
        offset = 0x800
[-25613773.708539]     status = 0
[-25613773.708546] DONE
[-25613773.708553] Sending response...
[-25613773.708676] Retrieving command...
[-25613773.708693] LAD_GATEMP_START: calling GateMP_start()...
[-25613773.708701]     status = 0
[-25613773.708708] DONE
[-25613773.708715] Sending response...
[-25613773.708744] Retrieving command...
[-25613773.708759] LAD_GATEMP_GETNUMRESOURCES: calling GateMP_getNumResources()...
[-25613773.708767]     status = 0
[-25613773.708774] DONE
[-25613773.708780] Sending response...
[-25613773.708822] Retrieving command...
[-25613773.708837] LAD_NAMESERVER_GET: calling NameServer_get(0x30228, '_GateMP_TI_dGate'[-25613773.708846] )...
[-25613773.708858] NameServer_getLocal: entry key: '_GateMP_TI_dGate' not found!
[-25613773.708867] NameServer_getRemote: no socket connection to processor 1
[-25613773.708875] NameServer_getRemote: no socket connection to processor 2
[-25613773.708881] NameServer_getRemote: no socket connection to processor 3
[-25613773.708889] NameServer_getRemote: no socket connection to processor 4
[-25613773.708896]     value = 0x10
[-25613773.708903]     status = -5
[-25613773.708909] DONE
[-25613773.708915] Sending response...
[-25613773.708965] Retrieving command...
[-25613773.708979] LAD_MESSAGEQ_CREATE: calling MessageQ_create(0x2f89c, 0x2f8bc)...
[-25613773.708988] MessageQ_create: creating 'HOST:MsgQ:01'
[-25613773.708998] MessageQ_create: returning obj=0x30640, qid=0x80
[-25613773.709007]     status = 0
[-25613773.709013] DONE
[-25613773.709020] Sending response...
[-25613773.709056] Retrieving command...
[-25613773.709071] LAD_MESSAGEQ_ANNOUNCE: calling MessageQ_announce(0x2f89c, 0x30640)...
[-25613773.709079] MessageQ_announce: announcing 0x30640
[-25613773.709090] NameServer_add: Entered key: 'HOST:MsgQ:01', data: 0x80
[-25613773.709099]     status = 0
[-25613773.709106] DONE
[-25613773.709113] Sending response...
[-25613773.709173] Retrieving command...
[-25613773.709188] LAD_NAMESERVER_GETUINT32: calling NameServer_getUInt32(0x30558, 'DSP1:MsgQ:01')...
[-25613773.709198] NameServer_getLocal: entry key: 'DSP1:MsgQ:01' not found!
[-25613773.709207] NameServer_getRemote: no socket connection to processor 1
[-25613773.709214] NameServer_getRemote: no socket connection to processor 2
[-25613773.709221] NameServer_getRemote: no socket connection to processor 3
[-25613773.709228] NameServer_getRemote: no socket connection to processor 4
[-25613773.709235]     value = 0x80
[-25613773.709241]     status = -5
[-25613773.709248] DONE
[-25613773.709255] Sending response...
[-25613773.709294] Retrieving command...
[-25613772.709403] LAD_NAMESERVER_GETUINT32: calling NameServer_getUInt32(0x30558, 'DSP1:MsgQ:01')...
[-25613772.709436] NameServer_getLocal: entry key: 'DSP1:MsgQ:01' not found!
[-25613772.709448] NameServer_getRemote: no socket connection to processor 1
[-25613772.709456] NameServer_getRemote: no socket connection to processor 2
[-25613772.709464] NameServer_getRemote: no socket connection to processor 3
[-25613772.709471] NameServer_getRemote: no socket connection to processor 4
[-25613772.709478]     value = 0x80
[-25613772.709486]     status = -5
[-25613772.709493] DONE
[-25613772.709500] Sending response...
[-25613772.709517] Retrieving command...
[-25613771.709645] LAD_NAMESERVER_GETUINT32: calling NameServer_getUInt32(0x30558, 'DSP1:MsgQ:01')...
[-25613771.709670] NameServer_getLocal: entry key: 'DSP1:MsgQ:01' not found!
[-25613771.709681] NameServer_getRemote: no socket connection to processor 1
[-25613771.709689] NameServer_getRemote: no socket connection to processor 2
[-25613771.709697] NameServer_getRemote: no socket connection to processor 3
[-25613771.709704] NameServer_getRemote: no socket connection to processor 4
[-25613771.709728]     value = 0x80
[-25613771.709737]     status = -5
[-25613771.709744] DONE
[-25613771.709750] Sending response...
[-25613771.709765] Retrieving command...
[-25613770.709893] LAD_NAMESERVER_GETUINT32: calling NameServer_getUInt32(0x30558, 'DSP1:MsgQ:01')...
[-25613770.709918] NameServer_getLocal: entry key: 'DSP1:MsgQ:01' not found!
[-25613770.709929] NameServer_getRemote: no socket connection to processor 1
[-25613770.709938] NameServer_getRemote: no socket connection to processor 2
[-25613770.709945] NameServer_getRemote: no socket connection to processor 3
[-25613770.709952] NameServer_getRemote: no socket connection to processor 4
[-25613770.709959]     value = 0x80
[-25613770.709967]     status = -5
[-25613770.709974] DONE
[-25613770.709980] Sending response...
[-25613770.709995] Retrieving command...
[-25613769.710120] LAD_NAMESERVER_GETUINT32: calling NameServer_getUInt32(0x30558, 'DSP1:MsgQ:01')...
[-25613769.710144] NameServer_getLocal: entry key: 'DSP1:MsgQ:01' not found!
[-25613769.710155] NameServer_getRemote: no socket connection to processor 1
[-25613769.710163] NameServer_getRemote: no socket connection to processor 2
[-25613769.710171] NameServer_getRemote: no socket connection to processor 3
[-25613769.710178] NameServer_getRemote: no socket connection to processor 4
[-25613769.710185]     value = 0x80
[-25613769.710193]     status = -5
[-25613769.710200] DONE
[-25613769.710207] Sending response...
[-25613769.710221] Retrieving command...
[-25613768.710342] LAD_NAMESERVER_GETUINT32: calling NameServer_getUInt32(0x30558, 'DSP1:MsgQ:01')...
[-25613768.710365] NameServer_getLocal: entry key: 'DSP1:MsgQ:01' not found!
[-25613768.710376] NameServer_getRemote: no socket connection to processor 1
[-25613768.710384] NameServer_getRemote: no socket connection to processor 2
[-25613768.710392] NameServer_getRemote: no socket connection to processor 3
[-25613768.710399] NameServer_getRemote: no socket connection to processor 4
[-25613768.710407]     value = 0x80
[-25613768.710414]     status = -5
[-25613768.710421] DONE
[-25613768.710427] Sending response...
[-25613768.710442] Retrieving command...
[-25613767.710564] LAD_NAMESERVER_GETUINT32: calling NameServer_getUInt32(0x30558, 'DSP1:MsgQ:01')...
[-25613767.710587] NameServer_getLocal: entry key: 'DSP1:MsgQ:01' not found!
[-25613767.710597] NameServer_getRemote: no socket connection to processor 1
[-25613767.710606] NameServer_getRemote: no socket connection to processor 2
[-25613767.710613] NameServer_getRemote: no socket connection to processor 3
[-25613767.710620] NameServer_getRemote: no socket connection to processor 4
[-25613767.710627]     value = 0x80
[-25613767.710634]     status = -5
[-25613767.710641] DONE
[-25613767.710648] Sending response...
[-25613767.710662] Retrieving command...
[-25613766.710782] LAD_NAMESERVER_GETUINT32: calling NameServer_getUInt32(0x30558, 'DSP1:MsgQ:01')...
[-25613766.710805] NameServer_getLocal: entry key: 'DSP1:MsgQ:01' not found!
[-25613766.710815] NameServer_getRemote: no socket connection to processor 1
[-25613766.710823] NameServer_getRemote: no socket connection to processor 2
[-25613766.710831] NameServer_getRemote: no socket connection to processor 3
[-25613766.710838] NameServer_getRemote: no socket connection to processor 4
[-25613766.710845]     value = 0x80
[-25613766.710853]     status = -5
[-25613766.710859] DONE
[-25613766.710865] Sending response...
[-25613766.710880] Retrieving command...
[-25613765.711005] LAD_NAMESERVER_GETUINT32: calling NameServer_getUInt32(0x30558, 'DSP1:MsgQ:01')...
[-25613765.711027] NameServer_getLocal: entry key: 'DSP1:MsgQ:01' not found!
[-25613765.711037] NameServer_getRemote: no socket connection to processor 1
[-25613765.711046] NameServer_getRemote: no socket connection to processor 2
[-25613765.711053] NameServer_getRemote: no socket connection to processor 3
[-25613765.711061] NameServer_getRemote: no socket connection to processor 4
[-25613765.711068]     value = 0x80
[-25613765.711076]     status = -5
[-25613765.711083] DONE
[-25613765.711105] Sending response...
[-25613765.711121] Retrieving command...
[-25613764.711242] LAD_NAMESERVER_GETUINT32: calling NameServer_getUInt32(0x30558, 'DSP1:MsgQ:01')...
[-25613764.711265] NameServer_getLocal: entry key: 'DSP1:MsgQ:01' not found!
[-25613764.711276] NameServer_getRemote: no socket connection to processor 1
[-25613764.711284] NameServer_getRemote: no socket connection to processor 2
[-25613764.711292] NameServer_getRemote: no socket connection to processor 3
[-25613764.711299] NameServer_getRemote: no socket connection to processor 4
[-25613764.711306]     value = 0x80
[-25613764.711314]     status = -5
[-25613764.711320] DONE
[-25613764.711327] Sending response...
[-25613764.711341] Retrieving command...
[-25613764.711638] LAD_MESSAGEQ_DESTROY: calling MessageQ_destroy()...
[-25613764.711652] MessageQ_destroy: entered, refCount=1
[-25613764.711660] MessageQ_delete: deleting 0x30640
[-25613764.711678] MessageQ_delete: returning 0
[-25613764.711693] MessageQ_destroy: exiting, refCount=0
[-25613764.711701]     status = 0
[-25613764.711708] DONE
[-25613764.711715] Sending response...
[-25613764.711728] Retrieving command...
[-25613764.711769] LAD_NAMESERVER_DESTROY: calling NameServer_destroy()...
[-25613764.711779] NameServer_destroy: entered, refCount=2
[-25613764.711786] NameServer_destroy(): refCount(1) > 0, exiting
[-25613764.711794] NameServer_destroy: exiting, refCount=1
[-25613764.711801]     status = 0
[-25613764.711808] DONE
[-25613764.711815] Sending response...
[-25613764.711827] Retrieving command...
[-25613764.711961]
LAD_DISCONNECT: [-25613764.711973]
    client handle = 0[-25613764.711980]
    closing FIFO /tmp/LAD/302 (filePtr=0x303f0)
[-25613764.712020]     done, unlinking /tmp/LAD/302
[-25613764.712052] DONE
[-25613764.712061] Retrieving command...
[-25613763.101535]    EOF detected on FIFO, closing FIFO: /tmp/LAD/LADCMDS
[-25613763.101603]
    opening FIFO: /tmp/LAD/LADCMDS

  • Based on the LAD logs, it looks like in the failing case, no remoteprocs are up before the application attempts communication.

    When the issue happens, are you able to see the state of the remoteproc, and that it is running and in a good state (you can check this with debufs)? Is it possible that the user space application is started before the remote core is booted?

    Thanks,

    Angela

  • By using debugfs you mean to check the output of

    /sys/class/remoteproc/remoteproc2/state

    ?

    The

    /sys/kernel/debug/remoteproc/remoteproc2

    directory doesn't seem to have anything useful.

    Well it is possible the app starts while remote core isn't ready only if we assume that remote core booting can finish after kernel has finished booting. That would mean remote core finishes booting when user space is already accessible. Would that be possible?

    Unfortunately we are limited in testing since the setup that fails isn't the in-house one.

  • I meant the /sys/kernel/debug/remoteproc/remoteprocX/ path. There you can query the state as well as look at remoteproc traces like this:

    cat /sys/kernel/debug/remoteprocX/trace0

    And check if the traces look as expected for your firmware for proper booting. You can also check your dmesg logs for traces related to remoteproc and rpmsg to see if communication over rpmsg-proto has been established. You should see some trace similar to:

    virtio_rpmsg_bus virtio0: creating channel rpmsg-proto addr 0x3d

    Remoteproc will load the firmware and release the remotecore from reset during kernel boot. But if remotecore firmware has not yet registered the rpmsg-proto service with the host for some reason by the time the app starts, then NameServer_attach would fail. Registering the rpmsg-proto service with the host happens during IpcMgr_ipcStartup on the remote core.

    Can you share which SDK and IPC release you are using? Is it Ipc_start() that is failing or MessageQ_open()? If you retry your application after the failure is it able to succeed?

    Thanks,

    Angela

  • Hi Angela!

    We have confirmed that the DSP state is offline.

    Which is the best way to make sure that the "rpmsg-proto service" has been registered on the host?

    Simply busy-waiting for state becoming running is probably a bit too early as you say that the registering takes place in IpcMgr_ipcStartup. Is there a good way on Linux to find out when it's 100% safe to call Ipc_start()?

    /Marcus

  • Hi Marcus,

    Can you let us know which SDK release you are using?

    Making sure state is running is a good first step.

    All rpmsg_proto devices will show up as "rpmsgX" (where X is a number assigned at creation time) in sysfs in the following path:

    /sys/bus/rpmsg/drivers/rpmsg_proto/

    To check for a particular core, you should be able to see a name entry similar to the following for your remoteproc when the service has been registered. For example, for IPU2:

    /sys/bus/platform/devices/55020000.ipu/remoteproc1/virtio0/rpmsg0/name

    If you read the name and it returns "rpmsg-proto", then it is registered for that core.

    Note that remoteprocX, virtioX and rpmsgX numbers are all dynamic. So, depending on which core you are checking and what other cores are running in the system, these numbers might be different.

    Thanks,

    Angela

  • Hi Angela!

    On the system there exists three files /sys/bus/platform/devices/40800000.dsp/remoteprocX/virtioY/rpmsgZ/name exists for X=1, Y=0i and Z=[0;2]. Do we need to check all 3 rpmsgZ/name?

    /Marcus

  • Hi Marcus,

    You can check until you find one that is named "rpmsg-proto". That should be sufficient to say that the rpmsg_proto device is bound to the driver.

    Thanks,

    Angela

  • Hi Marcus,

    I haven't heard back from you, I'm assuming you were able to resolve your issue.

    If not, just post a reply below (or create a new thread if the thread has locked due to time-out).

     

    Thanks,

    Angela

  • Thanks Angela!

    Your answers resolved the issue. Please close thread.

    Regards,

    Marcus