| Priority | medium |
|---|---|
| Bug ID | 59982 |
| Assignee | dri-devel@lists.freedesktop.org |
| Summary | Radeon: evergreen Atombios in loop during initialization on ppc64 |
| Severity | normal |
| Classification | Unclassified |
| OS | All |
| Reporter | lucaskt@linux.vnet.ibm.com |
| Hardware | Other |
| Status | NEW |
| Version | XOrg CVS |
| Component | DRM/Radeon |
| Product | DRI |
Created attachment 73788 [details] Log for module insertion errors on mainline During the initialization of an evergreen adapter on ppc64 there are a lot of atombios problems reported, though none seems fatal. This is in sequence to bug #59672. Though this is now being run on the 3.8.0-rc5 kernel. The problem is basically a bunch of messages like: [ 854.915511] [drm:drm_vblank_get], enabling vblank on crtc 0, ret: 0 [ 854.915520] [drm:drm_calc_vbltimestamp_from_scanoutpos], crtc 0: Noop due to uninitialized mode. [ 854.915526] [drm:drm_update_vblank_count], enabling vblank interrupts on crtc 0, missed -1 [ 859.924406] [drm:atom_op_jump] *ERROR* atombios stuck in loop for more than 5secs aborting [ 859.924416] [drm:atom_execute_table_locked] *ERROR* atombios stuck executing C898 (len 62, WS 0, PS 0) @ 0xC8B4 A full dump is included as an attachment.
| What | Removed | Added |
|---|---|---|
| CC | lucaskt@linux.vnet.ibm.com | |
| See Also | https://bugs.freedesktop.org/show_bug.cgi?id=59672 |
cd /sys/bus/pci/devices/0000:01:05.0 sudo sh -c "echo 1 > rom" sudo sh -c "cat rom > ~/bios.rom" Something like that should do the trick, just change the pciid
Hi Jerome, I attempted the dump without success [root@localhost ~]# lspci ... 0001:01:00.0 VGA compatible controller: ATI Technologies Inc ... 0001:01:00.1 Audio device: ATI Technologies Inc ... [root@localhost ~]# cd /sys/bus/pci/devices/0001:01:00.0 [root@localhost 0001:01:00.0]# echo 1 > rom [root@localhost 0001:01:00.0]# cat rom > ~/bios.rom [ 588.381813] pci 0001:01:00.0: Invalid ROM contents cat: rom: Input/output error [root@localhost 0001:01:00.0]# lspci [ 637.187942] Kernel panic - not syncing: FAIL ... [ 637.190672] =============================== [ 637.190677] [ INFO: suspicious RCU usage. ] [ 637.190683] 3.8.0-rc5-kotd+ #6 Not tainted [ 637.190687] ------------------------------- [ 637.190692] include/linux/rcupdate.h:468 Illegal context switch in RCU read-side critical section! ... I'm investigating what was wrong with the rom dump, but if you have any ideas what it could be, any help would be appreciated :)
As a side note, the kernel panic is actually induced by me. It actually means there was an access to an invalid address.
Can you try dumping the bios when booting with kms disable and nothing bind to the gpu
Created attachment 73987 [details]
BIOS for the adapter
Here's the dump you requested, thanks for the reminder on modeset, was trying
to achieve it via a pci_enable/io_remap on a quirk.
Created attachment 73997 [details] [review] possible fix For some reason the current crtc enabled bit isn't going low. It should be low already if the crtc is off, but perhaps it has to have been on previously for it to go low. I guessing that since this is a ppc system, the card was never previously posted so the display was off before the driver loaded. This patch checks to see what the current state of the crtcs are at driver load time. That way we can skip disabling the display if it's already off. That said, the messages are harmless in this case.
Here is how we try to figure out atombios stuck. We use the atombios disasm : git://people.freedesktop.org/~mhopf/AtomDis To produce a readable file ./atomdis bios.rom > bios.txt Then when you get a message such as : *ERROR* atombios stuck executing C898 (len 62, WS 0, PS 0) @ 0xC8B4 It means it's stuck executing function that is at offset 0xc898 (look for c898 in your disasm output it's EnableCRTC. Inside that atombios function it's stuck in a loop. 0xC8B4 is the offset of the instruction at which the loop was interrupted (from one run to the other this offset might point to a different instruction in the same loop). So when you look at EnableCRTC it's stuck executing 0xC8B4 - 0xC898 = 0x1c which is : 001c: 4aa59c1b01 TEST reg[1b9c] [.X..] <- 01 0021: 491c00 JUMP_NotEqual 001c So test here test that register (0x1b9c << 2) ie register 0x6e70 as value of : 0x..01.... or if you prefer : (READREG(0x6e70) & 0x00ff0000) == 0x00010000 Lucas if you have any more atombios stuck don't hesitate to add them here. To find the register meaning you can grep the various header files of drivers/gpu/drm/radeon/ mostly evergreen one and modesetting one.
Hi Jerome, thanks for the tips.
Well, I followed the next error
[drm:atom_op_jump] *ERROR* atombios stuck in loop for more than 5secs aborting
[drm:atom_execute_table_locked] *ERROR* atombios stuck executing CC68 (len 72,
WS 0, PS 0) @ 0xCC97
Down to the test in 0x2f on 0xcc68.
command_table 0000cc68 #2c (UpdateCRTC_DoubleBufferRegisters):
...
0027: 5420b51b CLEAR reg[1bb5] [...X]
002b: 5420bd1b CLEAR reg[1bbd] [...X]
002f: 4a25b61b01 TEST reg[1bb6] [...X] <- 01
I have a question here: how do I determine what are these registers? I couldn't
match 1bb6 to anything on the radeon driver code, so I suppose that's somewhere
else... or is there some other way to read that?
Anyway, I backtracked that code back to this call on atombios_crtc.c:
static void atombios_lock_crtc(struct drm_crtc *crtc, int lock)
{
...
int index =
GetIndexIntoMasterTable(COMMAND, UpdateCRTC_DoubleBufferRegisters);
...
atom_execute_table(rdev->mode_info.atom_context, index, (uint32_t *)&args);
}
which could've come from either of these:
static void atombios_crtc_prepare(struct drm_crtc *crtc)
static void atombios_crtc_commit(struct drm_crtc *crtc)
Since those are callbacks registered as helper funcs, and I'm not sure of their
semantics, I ended up getting stuck :)
static const struct drm_crtc_helper_funcs atombios_helper_funcs = {
.prepare = atombios_crtc_prepare,
.commit = atombios_crtc_commit,
Any ideas here?
Thanks! :)
Nevermind the question about the registers, just re-read your post, which I should've done in the first place :) Thanks
UpdateCRTC_DoubleBufferRegisters takes the crtc hardware lock so that updates
happen atomically rather than double buffered updates during the vupdate
period.
You pass parameters to the atom table via a struct, in this case,
ENABLE_CRTC_PS_ALLOCATION.
args.ucCRTC = radeon_crtc->crtc_id;
args.ucEnable = lock;
0006: 370000 SET_ATI_PORT 0000 (INDIRECT_IO_MM)
Select the mmio register aperture.
0009: 5214 CALL_TABLE 14
(ASIC_StaticPwrMgtStatusChange/SetUniphyInstance)
SetUniphyInstance updates the offset for the selected crtc based on args.ucCRTC
parameter.
000b: 0765b61bfe AND reg[1bb6] [..X.] <- fe
This enables enables double buffering.
0010: 3d650001 COMP param[00] [..X.] <- 01
This checks the params to see is we are enabling the lock (args.ucEnable =
ATOM_ENABLE) or disabling the lock (args.ucEnable = ATOM_DISABLE).
0014: 443b00 JUMP_Equal 003b
If args.ucEnable == ATOM_ENABLE, jump to table offset 0x003b.
Drop the lock (args.ucEnable = ATOM_DISABLE).
0017: 5430761a CLEAR reg[1a76] [.X..]
001b: 54306e1a CLEAR reg[1a6e] [.X..]
001f: 5430271a CLEAR reg[1a27] [.X..]
0023: 5430111a CLEAR reg[1a11] [.X..]
0027: 5420b51b CLEAR reg[1bb5] [...X]
002b: 5420bd1b CLEAR reg[1bbd] [...X]
002f: 4a25b61b01 TEST reg[1bb6] [...X] <- 01
This tests the CRTC_DOUBLE_BUFFER_CONTROL.CRTC_UPDATE_PENDING bit.
0034: 492f00 JUMP_NotEqual 002f
If the bit is high, we jump back to 0x002f. If the bit is low, we're done.
0037: 3a0000 SET_REG_BLOCK 0000
003a: 5b EOT
Take the lock (args.ucEnable = ATOM_ENABLE).
003b: 0d25bd1b01 OR reg[1bbd] [...X] <- 01
0040: 54009e1b CLEAR reg[1b9e] [XXXX]
0044: 3a0000 SET_REG_BLOCK 0000
0047: 5b EOT
Just like in the other table, for some reason, the bit never goes low.
Thanks for clarifying those things! Well, I ran into a brand new set of questions while pursuing this. > 0006: 370000 SET_ATI_PORT 0000 (INDIRECT_IO_MM) > Select the mmio register aperture. This sounds like selecting BARs, but from what I see, Region 0 would be the framebuffer (256M) and Region 2 would be the MMIO registers. Or how are those addresses mapped from within the adapter? Or does that mean that there are multiple register banks and you're picking one? > 0009: 5214 CALL_TABLE 14 >(ASIC_StaticPwrMgtStatusChange/SetUniphyInstance) >SetUniphyInstance updates the offset for the selected crtc based on args.ucCRTC >parameter. How are parameters passed here? Does it get the same parameters that the first call received? I take it, the reference for param[00] there means ucCRTC, then. Is that it? > 0010: 3d650001 COMP param[00] [..X.] <- 01 > This checks the params to see is we are enabling the lock (args.ucEnable = > ATOM_ENABLE) or disabling the lock (args.ucEnable = ATOM_DISABLE) Ok, so, why is now param[00] referencing ucEnable? What is the reference to ucCRTC here? > 0034: 492f00 JUMP_NotEqual 002f > If the bit is high, we jump back to 0x002f. If the bit is low, we're done. So, the bit being low here means we don't have an update pending. Does it being high mean that the lock is still in effect (i.e. the CLEAR commands didn't take the disables down?)? > 0044: 3a0000 SET_REG_BLOCK 0000 > 0047: 5b EOT This seems to me like stack cleanup and return (I'm guessing EOT is End Of Table). Is that correct? On the kernel driver side, I couldn't find who is calling, or what's the purpose of the crtc_prepare and crtc_commit functions, which are the only ones apparently using this call (atombios_lock_crtc). What are they meant to do? Thanks
(In reply to comment #13) > Thanks for clarifying those things! > > Well, I ran into a brand new set of questions while pursuing this. > > > 0006: 370000 SET_ATI_PORT 0000 (INDIRECT_IO_MM) > > Select the mmio register aperture. > > This sounds like selecting BARs, but from what I see, Region 0 would be the > framebuffer (256M) and Region 2 would be the MMIO registers. Or how are > those addresses mapped from within the adapter? Or does that mean that there > are multiple register banks and you're picking one? No. There's only one register BAR. It's for selecting between the register BAR and pci config registers. See atom_op_setport(). I've never seen a table actually use anything other than the register BAR however. > > > 0009: 5214 CALL_TABLE 14 > >(ASIC_StaticPwrMgtStatusChange/SetUniphyInstance) > >SetUniphyInstance updates the offset for the selected crtc based on args.ucCRTC >parameter. > > How are parameters passed here? Does it get the same parameters that the > first call received? I take it, the reference for param[00] there means > ucCRTC, then. Is that it? They are passed to the table for execution. See atom_execute_table(). That function takes an atom context, an index (which table to execute), and pointer to the parameter struct. > > > 0010: 3d650001 COMP param[00] [..X.] <- 01 > > This checks the params to see is we are enabling the lock (args.ucEnable = > > ATOM_ENABLE) or disabling the lock (args.ucEnable = ATOM_DISABLE) > > Ok, so, why is now param[00] referencing ucEnable? What is the reference to > ucCRTC here? See atombios_lock_crtc(). Use this parameter struct with the UpdateCRTC_DoubleBufferRegisters table: typedef struct _ENABLE_CRTC_PARAMETERS { UCHAR ucCRTC; UCHAR ucEnable; UCHAR ucPadding[2]; }ENABLE_CRTC_PARAMETERS; See atombios.h. The parameter struct is 1 dword. The first byte is ucCRTC and the second byte is ucEnable. > > > 0034: 492f00 JUMP_NotEqual 002f > > If the bit is high, we jump back to 0x002f. If the bit is low, we're done. > > So, the bit being low here means we don't have an update pending. Does it > being high mean that the lock is still in effect (i.e. the CLEAR commands > didn't take the disables down?)? If the bit is high it means there is an update pending. E.g., some change in the crtc state hasn't gone through yet. I'm not sure why you are seeing it stuck high. > > > 0044: 3a0000 SET_REG_BLOCK 0000 > > 0047: 5b EOT > > This seems to me like stack cleanup and return (I'm guessing EOT is End Of > Table). Is that correct? Yes. correct. > > On the kernel driver side, I couldn't find who is calling, or what's the > purpose of the crtc_prepare and crtc_commit functions, which are the only > ones apparently using this call (atombios_lock_crtc). What are they meant to > do? crtc_prepare() and crtc_commit() are called before and after a modeset on the crtc object. See drm_crtc_helper_set_mode() in drm_crtc_helper.c. In atombios_crtc_prepare() we take the crtc hardware lock so that all updates will happen atomically, then we disable the crtc. Then in atombios_crtc_mode_set() we set up the pll, set the crtc timing, graphics plane base address, and scaler. Finally in atombios_crtc_commit() we enable the crtc and drop the crtc hardware lock.
Can someone clarify something here? Is the bit that we are waiting to go low a bit in the adapter's memory? If so, is it the adapter hardware that we are waiting to set this bit? Is there anyway to dump the adapter to determine its state when we hit the timeout?
(In reply to comment #15) > Can someone clarify something here? Is the bit that we are waiting to go low > a bit in the adapter's memory? If so, is it the adapter hardware that we are > waiting to set this bit? It's a memory mapped register. We are waiting for one of the display related bits to go low, so it's the GPU that would be setting that bit. The timeout is in the driver. We eventually drop out of the loop in the atom interpretor if we get stuck after a certain number of seconds. > > Is there anyway to dump the adapter to determine its state when we hit the > timeout? You can dump the mmio registers.
Created attachment 75176 [details] [review] Dumping registers to investigate values change Ok, so now I've tried dumping the register we're waiting for using this patch, and the output looks like this: OR_REG @ 0xD8EA EVERGREEN_CRTC_BLANK_CONTROL: 0001 0x6ED8: 10000 dst: REG[0x19A4].[7:0] -> 0x04 src: PS[0x00,0x0000].[7:0] -> 0x00 dst: REG[0x19A4].[7:0] <- 0x04 EOT @ 0xD8EF EVERGREEN_CRTC_BLANK_CONTROL: 0001 0x6ED8: 10000 << >> execute E82E (len 91, WS 0, PS 0) MOVE_PS @ 0xE834 EVERGREEN_CRTC_BLANK_CONTROL: ffffffff 0x6ED8: ffffffff I'm dumping 0x6ED8 as it is the register whose bit never goes down. Following this, all references to either register are All F's. I'm wondering if this could be my testing interfering with the adapter operation, or if this is really what's going on, as it could indicate other problems. Can I be dumping these registers there? Does that interfere with tests? Should I dump another register for testing? Which one would be best? >>From the 0xD8EA address, I can conclude it was executing the DAC1OutputControl function from the atombios that exited sucessfully. I'm investigating what happens afterwards that trigger this. Is it interrupt activation? Right now we're having to use LSIs, so it might be a problem there. Thanks
So when all register return 0xffffffff it's because something went horribly wrong. Either the GPU memory controller is lockup or in bad or the IOMMU is blocking things. My guess is that enabling the crtc to start scanning trigger request to the GPU memory controller and those request points to bad address. I would tripple check the memory controller setup and that the crtc base register points to valid vram inside the GPU memory address space.
Also does the ring/ib test that happen prior to any modesetting report success ?
Created attachment 75183 [details] [review] dumping Ok so dump reg that might trigger the GPU memory controller to start faulting.
Created attachment 75196 [details] [review] Fixes on the Workaround Ok, there were some minor issues with the workaround which are fixed here The output is: [drm] ring test on 3 succeeded in 1 usecs [drm] GRPH_PRIMARY_SURFACE[ 0] 0x0000000000000000 [drm] GRPH_SECONDARY_SURFACE[ 0] 0x0000000000000000 [drm] GRPH_PRIMARY_SURFACE[ 1] 0x0000000000000000 [drm] GRPH_SECONDARY_SURFACE[ 1] 0x0000000000000000 [drm] GRPH_PRIMARY_SURFACE[ 2] 0x0000000000000000 [drm] GRPH_SECONDARY_SURFACE[ 2] 0x0000000000000000 [drm] GRPH_PRIMARY_SURFACE[ 3] 0x0000000000000000 [drm] GRPH_SECONDARY_SURFACE[ 3] 0x0000000000000000 [drm] ib test on ring 0 succeeded in 0 usecs And there's no longer a "stuck in loop" message, but the registers do become all f's. I'm investigating exactly where, to see if it's still the same issue.
What is weird is that it's showing reg all with 0 value which would mean that my patch does nothing but still you seem to go further along. Probably me doing bad casting can you add (uint64_t) in front of each RREG32 in my patch and see if it still print 0000000000000
| What | Removed | Added |
|---|---|---|
| Attachment #75196 is obsolete | 1 |