Ø - check if the bus error is 'real', i.e., try to access the reported VME address e.g., from the console
(keeping in mind that A32 as seen from the CPU may be at an offset - depending on OS/BSP).
This is the system VME memory map:
iocexample> sysVmeMapShow
VMEbus access from CPU:
0x80000000 - 0xBFFFFFFF => A32: 0x80000000 - 0xBFFFFFFF
0xF0000000 - 0xF0FFFFFF => A24: 0x000000 - 0xFFFFFF
0xFBFF0000 - 0xFBFFFFFF => A16: 0x0000 - 0xFFFF
0xF2000000 - 0xF2FFFFFF => CR/CSR:0x000000 - 0xFFFFFF
PCIbus access from VMEbus:
A32: 0x80000000 - 0x9FFFFFFF => RAM: 0x00000000 - 0x1FFFFFFF
value = 0 = 0x0
The A16 errors are all at addresses like this, i.e. address 0x34xx
[Fri May 27 14:05:24 2022] VME Bus Error accessing A16: 0x345e
[Fri May 27 14:20:20 2022] VME Bus Error accessing A16: 0x345e
[Fri May 27 15:49:10 2022] VME Bus Error accessing A16: 0x345e
[Fri May 27 15:49:57 2022] VME Bus Error accessing A16: 0x347e
[Fri May 27 16:15:55 2022] VME Bus Error accessing A16: 0x345e
[Fri May 27 16:39:39 2022] VME Bus Error accessing A16: 0x345e
[Tue May 31 17:59:31 2022] VME Bus Error accessing A16: 0x347e
[Tue May 31 22:09:43 2022] VME Bus Error accessing A16: 0x347e
The A32 VME bus errors are all at addresses like these, i.e. addresses 0xbfxxxxxx.
[Tue May 31 16:09:11 2022] VME Bus Error accessing A32: 0xbfe3332c
[Tue May 31 16:11:01 2022] VME Bus Error accessing A32: 0xbfdffff8
[Tue May 31 18:47:53 2022] VME Bus Error accessing A32: 0xbffb3330
[Tue May 31 18:47:54 2022] VME Bus Error accessing A32: 0xbfe99994
[Tue May 31 18:47:54 2022] VME Bus Error accessing A32: 0xbfe692d4
[Wed Jun 1 07:29:53 2022] VME Bus Error accessing A32: 0xbffcf67c
[Wed Jun 1 11:29:14 2022] VME Bus Error accessing A32: 0xbfa8c418
For these tests I only have a single VME card installed, other than the MVME5100 CPU. That card is a TVME200 IP carrier. It is configured with this command:
# The second carrier in our system is a TEWS TVME200
# The argument to ipacAddTVME200 is the values of the 6 switches on the board
# In this case 34 = base address 3400
# 2 = interrupt mapping 4, 5, 2, 1, 4, 5, 2, 1
# F = A32 address space, 8MB per slot, 32MB total
# A2 = A2000000 base address in A32 space
ipacAddTVME200("342FA2")
This means that the card occupies 0x3400 to 0x37FF in the A16 address space, each of the 4 IP slots used 0x100 bytes. The IP330 module is in slot 0, so it uses addresses 0x3400 – 0x34ff.
The VME bus errors are all at address 0x345e or 0x347e. This means they are in the mailbox register space of the IP330 card. Those addresses should not generate a bus error on a read operation. But if it was a write operation then it should generate a bus error. This is a memory dump of the A16 memory for the IP330. Note that we can indeed read address 0x345e and 0x347e.
iocexample> d 0xfbff3400
NOTE: memory values are displayed in hexadecimal.
0xfbff3400: 2b02 4078 0021 0f00 0000 0000 0000 0000 *+.@x.!..........*
0xfbff3410: 0000 0000 0000 0000 0000 0000 0000 0000 *................*
0xfbff3420: 0000 0000 0000 0000 0000 0000 0000 0000 *................*
0xfbff3430: 0000 0000 0000 0000 0000 0000 0000 0000 *................*
0xfbff3440: 16b8 1701 1701 1700 171b 16fe 170b 16f9 *................*
0xfbff3450: 1703 1702 16fa 16f4 170d 16ed 16fe 16e3 *................*
0xfbff3460: 16b6 169c 16a7 1c2f 1c4a 1c2c 1c36 2138 *......./.J.,.6!8*
0xfbff3470: 2db9 2dae 2d9a 2d86 330a 32e6 32ea 32cc *-.-.-.-.3.2.2.2.*
0xfbff3480: ff49 ff50 ff41 ff43 ffa3 ff11 ff00 ff00 *.I.P.A.C........*
0xfbff3490: ff00 ff00 ff0c ff5a ff00 ff00 ff00 ff00 *.......Z........*
0xfbff34a0: ff00 ff00 ff00 ff00 ff00 ff00 ff00 ff00 *................*
0xfbff34b0: ff00 ff00 ff00 ff00 ff00 ff00 ff00 ff00 *................*
0xfbff34c0: 0054 0000 0054 0000 0054 0000 0054 0000 *.T...T...T...T..*
0xfbff34d0: 0054 0000 0054 0000 0054 0000 0054 0000 *.T...T...T...T..*
0xfbff34e0: 0054 0000 0054 0000 0054 0000 0054 0000 *.T...T...T...T..*
0xfbff34f0: 0054 0000 0054 0000 0054 0000 0054 0000 *.T...T...T...T..*
value = 0 = 0x0
The A32 address errors are at 0xbfxxxxxx. That is at the very top of the A32 address space. That is not where the TVME200 card is located, it is at 0xA2000000. Those addresses are not readable, and do indeed generate an A32 bus error:
iocexample> *(0xbfe3332c)
VME Bus Error accessing A32: 0xbfe3332c
machine check
Exception next instruction address: 0x001fe4f4
Machine Status Register: 0x0008b032
Condition Register: 0x88000244
0x0012489c vxTaskEntry +0x48 : 0x0020c554 ()
0x0020c554 shellTask +0x4a8: shellExec ()
0x0020c020 shellExec +0x11c: 0x00201a78 ()
0x00201ca0 shellInterpCInit+0x640: shellInterpCparse ()
0x00201384 shellInterpCparse+0xa3c: 0x001fe9f4 ()
0x001fea24 shellInterpClex+0x1d6c: 0x001fe6dc ()
0x001fe7a0 shellInterpClex+0x1ae8: 0x001fe490 ()
Shell task 'tShell0' restarted...
So the A16 bus errors are at a “valid” address, but perhaps a write rather than a read is being done. The A32 addresses cannot be read, they do generate bus errors.
Mark
*From:* Till Straumann <till.straumann at psi.ch>
*Sent:* Wednesday, June 1, 2022 9:34 AM
*To:* Mark Rivers <rivers at cars.uchicago.edu>; Michael Davidsaver <mdavidsaver at gmail.com>; Torsten Bögershausen <Torsten.Bogershausen at ess.eu>; Benjamin Franksen <benjamin.franksen at helmholtz-berlin.de>
*Cc:* tech-talk at aps.anl.gov
*Subject:* Re: Bus errors accessing VME with base 7.0.6.1 and latest synApps modules
Hi Mark.
I'm sorry I missed the earlier post where you had indeed added the 'ti' information.
Could you please provide 'dbEvent.o' (from commit 85822f305) ?
Things I would try:
- check if the bus error is 'real', i.e., try to access the reported VME address e.g., from the console
(keeping in mind that A32 as seen from the CPU may be at an offset - depending on OS/BSP).
- if this is the case then you may deal (as suggested earlier by Michael, iirc) that the error is reported
in a delayed fashion. I would try to insert some 'no-op' just before the call to freeListFree() (make
sure it is not optimized away) and see where the exception happens.
- add a 'sanity-check' of 'pfl' and 'pfl->u.r.dtor' in 'db_delete_field_log()' and report if any of these
addresses is within a VME window.
I have seen similar things (late-reported bus error) but often we would then find the fault address
in one of the registers (or a combination of some 'base' + 'offset' in a couple of them) but I can't
see that in your register dump. It is still possible that it was in one of the caller-saved registers
and got wiped when the call to 'freeListFree()' was set up.
Cheers
- T.
On 6/1/22 14:50, Mark Rivers via Tech-talk wrote:
I agree that a debugger would be very helpful. I don't have that tool, but I think others at the APS do. I'll find out when Andrew returns next week. Meanwhile git bisect can help point in the right direction.
I tested this commit 85822f3051d2236144bb46dc2c24b7e38143e531 with soft records overnight. It ran for 32,000 seconds without failing before I stopped it.
The next commit, 56f05d722dee4b8ca2968b8bface2737a3a9b185, fails in less than 10 seconds in each of 3 tests.
I just tested with the IPAC hardware again with commit 85822f3051d2236144bb46dc2c24b7e38143e531 (which does not fail with soft records). It failed after 960 seconds with this error:
VME Bus Error accessing A32: 0xbffcf67c
machine check
Exception next instruction address: 0x03326a90
Machine Status Register: 0x0008b032
Condition Register: 0x42000884
Task: 0x3559330 "CAS-event"
0x3559330 (CAS-event): task 0x3559330 has had a failure and has been stopped.
0x3559330 (CAS-event): The task has been terminated because it triggered an exception that raised the signal 10.
This is the task trace:
iocexample> tt 0x3559330
0x0012489c vxTaskEntry +0x48 : epicsThreadEntry ()
0x0334501c epicsThreadEntry+0x80 : 0x032a17f0 ()
0x032a1acc db_start_events+0x450: db_delete_field_log ()
0x032a0fe4 db_delete_field_log+0x54 : freeListFree ()
value = 0 = 0x0
This tells us pretty clearly that the failure as in freeListFree, called by db_delete_field_log. That has been a very common stack trace for these errors.
Till complained that vxWorks did not provide a register dump, but that is not true, it is available with the “ti” command. I had included that in several previous messages. Here it is for this task.
iocexample> ti 0x3559330
NAME ENTRY TID PRI STATUS PC SP ERRNO DELAY
---------- ------------ -------- --- ---------- -------- -------- ------- -----
CAS-event epicsThread> 3559330 133 STOP+I 3326a90 3559240 0 0
full task name : CAS-event
task entry : epicsThreadEntry
process : kernel
options : 0x1009001
VX_SUPERVISOR_MODE VX_DEALLOC_TCB VX_FP_TASK VX_DEALLOC_EXC_STACK
STACK BASE END SP SIZE HIGH MARGIN
--------- -------- -------- -------- ------- ------- -------
execution 3559330 3556450 3559240 12000 2800 9200
exception 2700210 26ff3a0 3696 1344 2352
VxWorks Events
--------------
Events Pended on : Not Pended
Received Events : 0x0
Options : N/A
r0 = 0x40000000 sp = 0x03559240 r2 = 0x002f1ac0
r3 = 0x03492ce0 r4 = 0x0357bec8 r5 = 0x00000001
r6 = 0x00000001 r7 = 0x00000000 r8 = 0xeefceefd
r9 = 0x03326a90 r10 = 0x00000000 r11 = 0x035591b0
r12 = 0x20000884 r13 = 0x00321e60 r14 = 0x033b6098
r15 = 0x03373c64 r16 = 0x03289478 r17 = 0x033424f0
r18 = 0x03373bdc r19 = 0x03373c1c r20 = 0x032a0ff8
r21 = 0x032a0f90 r22 = 0x00000000 r23 = 0x00000001
r24 = 0x033b609c r25 = 0x03339340 r26 = 0x033390e0
r27 = 0x03443b60 r28 = 0x0357e748 r29 = 0x03567d78
r30 = 0x032dad44 r31 = 0x0357bec8 msr = 0x0008b032
lr = 0x032a0fe4 ctr = 0x03326a90 pc = 0x03326a90
cr = 0x42000884 xer = 0x00000000 pgTblPtr = 0x02310000
scSrTblPtr = 0x0230fe74 srTblPtr = 0x0230fe74
fpcsr = 0
fr0 = -1.81018 fr1 = NaN fr2 = NaN fr3 = NaN
fr4 = NaN fr5 = NaN fr6 = NaN fr7 = NaN
fr8 = NaN fr9 = NaN fr10 = NaN fr11 = NaN
fr12 = NaN fr13 = NaN fr14 = NaN fr15 = NaN
fr16 = NaN fr17 = NaN fr18 = NaN fr19 = NaN
fr20 = NaN fr21 = NaN fr22 = NaN fr23 = NaN
fr24 = NaN fr25 = NaN fr26 = NaN fr27 = NaN
fr28 = NaN fr29 = NaN fr30 = NaN fr31 = NaN
machine checkvalue =
Exception next instruction address: 0x003326a90
Machine Status Register: 0x = 0008b032
Condition Register: 0x420008840x
0
And here is the disassembly for freeListFree, where I have highlighted in red the "next instruction" above.
freeListFree:
0x3326a90 9421fff0 stwu r1,-16(r1)
0x3326a94 7c0802a6 mfspr r0,LR
0x3326a98 3d200334 lis r9,0x334 # 820
0x3326a9c 392990e0 addi r9,r9,0x90e0 # -28448
0x3326aa0 7d2903a6 mtspr CTR,r9
0x3326aa4 90010014 stw r0,20(r1)
0x3326aa8 93c10008 stw r30,8(r1)
0x3326aac 7c9e2378 or r30,r4,r4
0x3326ab0 93e1000c stw r31,12(r1)
0x3326ab4 7c7f1b78 or r31,r3,r3
0x3326ab8 80630014 lwz r3,20(r3)
0x3326abc 4e800421 bcctrl 0x14,0
0x3326ac0 2f830000 cmpi crf7,0,r3,0x0 # 0
0x3326ac4 41be002c bc 0xd,30, 0x3326af0 # 0x03326af0
0x3326ac8 3d200334 lis r9,0x334 # 820
0x3326acc 3c600338 lis r3,0x338 # 824
0x3326ad0 3ca00338 lis r5,0x338 # 824
0x3326ad4 392924f0 addi r9,r9,0x24f0 # 9456
0x3326ad8 386335a4 addi r3,r3,0x35a4 # 13732
0x3326adc 38a535c0 addi r5,r5,0x35c0 # 13760
0x3326ae0 7d2903a6 mtspr CTR,r9
0x3326ae4 3880008f li r4,0x8f # 143
0x3326ae8 38c00000 li r6,0x0 # 0
0x3326aec 4e800421 bcctrl 0x14,0
0x3326af0 813f0010 lwz r9,16(r31)
0x3326af4 801f0008 lwz r0,8(r31)
0x3326af8 39290001 addi r9,r9,0x1 # 1
0x3326afc 807f0014 lwz r3,20(r31)
0x3326b00 913f0010 stw r9,16(r31)
0x3326b04 3d200334 lis r9,0x334 # 820
0x3326b08 39299340 addi r9,r9,0x9340 # -27840
0x3326b0c 901e0000 stw r0,0(r30)
0x3326b10 7d2903a6 mtspr CTR,r9
0x3326b14 93df0008 stw r30,8(r31)
0x3326b18 4e800421 bcctrl 0x14,0
0x3326b1c 80010014 lwz r0,20(r1)
0x3326b20 83c10008 lwz r30,8(r1)
0x3326b24 7c0803a6 mtspr LR,r0
0x3326b28 83e1000c lwz r31,12(r1)
0x3326b2c 38210010 addi r1,r1,0x10 # 16
0x3326b30 4e800020 blr
This is the source code for freeListFree in this tag of base.
LIBCOM_API void epicsStdCall freeListFree(void *pvt,void*pmem)
{
FREELISTPVT *pfl = pvt;
# ifdef EPICS_FREELIST_DEBUG
memset ( pmem, 0xdd, pfl->size );
free(pmem);
# else
void **ppnext;
VALGRIND_MEMPOOL_FREE(pvt, pmem);
VALGRIND_MEMPOOL_ALLOC(pvt, pmem, sizeof(void*));
epicsMutexMustLock(pfl->lock);
ppnext = pmem;
*ppnext = pfl->head;
pfl->head = pmem;
pfl->nBlocksAvailable++;
epicsMutexUnlock(pfl->lock);
# endif
}
The last thing I will try is to git bisect from this commit 85822f3051d2236144bb46dc2c24b7e38143e531 to R7.0.5 to see where the hardware tests first begin to fail.
Mark
-----Original Message-----
From: Michael Davidsaver <mdavidsaver at gmail.com> <mailto:mdavidsaver at gmail.com>
Sent: Wednesday, June 1, 2022 1:40 AM
To: Torsten Bögershausen <Torsten.Bogershausen at ess.eu> <mailto:Torsten.Bogershausen at ess.eu>; Mark Rivers <rivers at cars.uchicago.edu> <mailto:rivers at cars.uchicago.edu>; Benjamin Franksen <benjamin.franksen at helmholtz-berlin.de> <mailto:benjamin.franksen at helmholtz-berlin.de>
Cc: tech-talk at aps.anl.gov <mailto:tech-talk at aps.anl.gov>
Subject: Re: Bus errors accessing VME with base 7.0.6.1 and latest synApps modules
On 5/31/22 07:00, Torsten Bögershausen wrote:
> Hej Mark,
>
> So R7.0.5 is good, and f9ea6a5bff695c5f88bb95dce38a3fd349738907 is bad ?
>
> There are some "real" commits, and merges:
> git log R7.0.5..f9ea6a5bff695c5f88bb95dce38a3fd349738907
>
> Then it could make sense, to bisect between those 2?
>
> Another question:
> Coluld it make sense to run the SW (even more stripped may be) under
> Linux instead with valgrind ?
An RTOS without a debugger is just about the worst situation I can imagine to troubleshoot apparent memory corruption. (excepting maybe having no console, or it being in orbit)
I've made an attempt to run the database Mark describes with
softIoc+valgrind, and a spam-y python script. Valgrind doesn't
flag any access violates.
The threading checker ("valgrind --tool=helgrind") does flag a possible race which might be relevant. Or it might be a false positive. I don't feel that I understand dbEvent.c well enough to say anything conclusive this late at night.
> Possible data race during write of size 8 at 0x5197520 by thread #27
> Locks held: 3, at addresses 0x51413A0 0x5143A60 0x5197A10
> at 0x48CA60A: db_queue_event_log (dbEvent.c:824)
> by 0x48CA732: db_post_events (dbEvent.c:892)
> by 0x48595EE: monitor (aoRecord.c:532)
> by 0x48595EE: process (aoRecord.c:232)
> by 0x48B2C6B: dbProcess (dbAccess.c:608)
> by 0x48B4BFF: dbPutField (dbAccess.c:1278)
> by 0x48CE9DD: dbChannel_put (db_access.c:923)
> by 0x48F6C9A: write_action (camessage.c:799)
> by 0x48F7727: camessage (camessage.c:2546)
> by 0x48F351F: camsgtask (camsgtask.c:116)
> by 0x495E094: start_routine (osdThread.c:439)
> by 0x483F876: mythread_wrapper (hg_intercepts.c:387)
> by 0x4F1EEA6: start_thread (pthread_create.c:477)
>
> This conflicts with a previous read of size 8 by thread #21 Locks
> held: none
> at 0x48CA99D: event_read (dbEvent.c:999)
> by 0x48CA99D: event_task (dbEvent.c:1078)
> by 0x495E094: start_routine (osdThread.c:439)
> by 0x483F876: mythread_wrapper (hg_intercepts.c:387)
> by 0x4F1EEA6: start_thread (pthread_create.c:477)
> by 0x4CBADEE: clone (clone.S:95)
> Address 0x5197520 is 18,416 bytes inside a block of size 19,528 alloc'd
> at 0x48397CF: malloc (vg_replace_malloc.c:307)
> by 0x494DBE1: freeListMalloc (freeListLib.c:95)
> by 0x494DCE8: freeListCalloc (freeListLib.c:68)
> by 0x48C95B2: db_init_events (dbEvent.c:304)
> by 0x48D653C: dbContext::subscribe(epicsGuard<epicsMutex>&, dbChannel*, dbChannelIO&, unsigned int, unsigned long, unsigned int, cacStateNotify&, unsigned int*) (dbContext.cpp:221)
> by 0x48D7468: dbChannelIO::subscribe(epicsGuard<epicsMutex>&, unsigned int, unsigned long, unsigned int, cacStateNotify&, unsigned int*) (dbChannelIO.cpp:119)
> by 0x4EF7771: oldSubscription::oldSubscription(epicsGuard<epicsMutex>&, oldChannelNotify&, cacChannel&, unsigned int, unsigned long, unsigned int, void (*)(event_handler_args), void*, oldSubscription**) (oldSubscription.cpp:43)
> by 0x4EF7099: ca_create_subscription (oldChannelNotify.cpp:573)
> by 0x48D2BE8: dbCaTask (dbCa.c:1249)
> by 0x495E094: start_routine (osdThread.c:439)
> by 0x483F876: mythread_wrapper (hg_intercepts.c:387)
> by 0x4F1EEA6: start_thread (pthread_create.c:477) Block was
> alloc'd by thread #9
https://github.com/epics-base/epics-base/blob/3fadf4a26cfe33dcb9eb9e4620634e1d3a7b9763/modules/database/src/ioc/db/dbEvent.c#L824 <https://github.com/epics-base/epics-base/blob/3fadf4a26cfe33dcb9eb9e4620634e1d3a7b9763/modules/database/src/ioc/db/dbEvent.c#L824>
https://github.com/epics-base/epics-base/blob/3fadf4a26cfe33dcb9eb9e4620634e1d3a7b9763/modules/database/src/ioc/db/dbEvent.c#L999 <https://github.com/epics-base/epics-base/blob/3fadf4a26cfe33dcb9eb9e4620634e1d3a7b9763/modules/database/src/ioc/db/dbEvent.c#L999>
> $ cat mr-regress.db
> record(ao,"testAo_0") {}
> record(ao,"testAo_1") {}
> record(ao,"testAo_2") {}
> record(ao,"testAo_3") {}
> record(ao,"testAo_4") {}
> record(ao,"testAo_5") {}
> record(ao,"testAo_6") {}
> record(ao,"testAo_7") {}
> record(ao,"testAo_8") {}
> record(ao,"testAo_9") {}
> record(ai,"testAi_0") {field(INP, "testAo_0 CP") }
> record(ai,"testAi_1") {field(INP, "testAo_1 CP") }
> record(ai,"testAi_2") {field(INP, "testAo_2 CP") }
> record(ai,"testAi_3") {field(INP, "testAo_3 CP") }
> record(ai,"testAi_4") {field(INP, "testAo_4 CP") }
> record(ai,"testAi_5") {field(INP, "testAo_5 CP") }
> record(ai,"testAi_6") {field(INP, "testAo_6 CP") }
> record(ai,"testAi_7") {field(INP, "testAo_7 CP") }
> record(ai,"testAi_8") {field(INP, "testAo_8 CP") }
> record(ai,"testAi_9") {field(INP, "testAo_9 CP") }
> $ valgrind --tool=helgrind ./bin/linux-x86_64/softIoc -d mr-regress.db
> $ ./bin/linux-x86_64/caput testAo_0 1.0
> $ ./bin/linux-x86_64/caput testAo_0 2.0
·
Home
·
News
·
About
·
Base
·
Modules
·
Extensions
·
Distributions
·
Download
·