[Qemu-devel] SPARC kernel oops with logging

[Qemu-devel] SPARC kernel oops with logging

[Gabriel Southern]

[-- Attachment #1: Type: text/plain, Size: 2199 bytes --]

Hi,

When I run qemu-system-sparc with -d in_asm,out_asm the Linux kernel
crashes when it tries to initialize the hard drive.  The same hard
drive image boots perfectly if I do not include the logging options.
The error messages that I receive are shown below.  I'm wondering if
the logging is causing some type of acknowledgment to be delayed and
this is causing a SCSI operation to timeout.  I've also attached log
of the complete console output in case anyone would find it useful.
If anyone has ideas about the cause or a possible solution please let
me know.

Thanks,

Gabriel

--------------------------------
Begin: Loading essential drivers... ...
SCSI subsystem initialized
esp0: IRQ 36 SCSI ID 7 Clk 40MHz CCYC=25000 CCF=8 TOut 167 NCR53C9XF(espfast)
scsi0 : Sparc ESP100A-FAST
Unable to handle kernel paging request at virtual address fe62f000
tsk->{mm,active_mm}->context = 0000007f
tsk->{mm,active_mm}->pgd = fc014400
              \|/ ____ \|/
              "@'/ ,. \`@"
              /_| \__/ |_\
                 \__U_/
modprobe(771): Oops [#1]
PSR: 04000fc7 PC: fe62f000 NPC: fe62f004 Y: fffffffc    Not tainted
PC: <__scsi_device_lookup_by_target+0x8/0x40 [scsi_mod]>
%G: ffffffff 04000fe0  00000000 044000e0  f0115c18 49ff53a9  f3274000 00000000
%O: f3249400 00000000  f3275a20 f3249484  f3249484 0000000c  f3275980 fe62f204
RPC: <scsi_device_lookup_by_target+0x44/0x74 [scsi_mod]>
%L: 040000e0 fe6362e8  fe6363cc 00000004  00000008 00000000  00000000 0000000a
%I: f3249400 00000000  00000000 00000000  00000000 f9828000  f32759e8 fe635528
Caller[fe635528]: scsi_probe_and_add_lun+0x40/0x9f4 [scsi_mod]
Caller[fe63641c]: __scsi_scan_target+0xa8/0x5a8 [scsi_mod]
Caller[fe63696c]: scsi_scan_channel+0x50/0x74 [scsi_mod]
Caller[fe636a1c]: scsi_scan_host_selected+0x8c/0xd8 [scsi_mod]
Caller[fe61ec80]: esp_sbus_probe+0x9f4/0xae8 [esp]
Caller[f001ba48]: of_device_probe+0x58/0x74
Caller[f01176b4]: driver_probe_device+0x60/0xb8
Caller[f0117814]: __driver_attach+0x70/0xc4
Caller[f0116f9c]: bus_for_each_dev+0x40/0x74
Caller[f0116bec]: bus_add_driver+0x6c/0x134
Caller[f004c86c]: sys_init_module+0x1610/0x1778
Caller[f0011634]: syscall_is_too_hard+0x3c/0x40
Caller[000133b4]: 0x133bc

[-- Attachment #2: sparc_qemu_crash.log --]
[-- Type: application/octet-stream, Size: 6726 bytes --]

Configuration device id QEMU version 1 machine id 32
UUID: 00000000-0000-0000-0000-000000000000
CPUs: 1 x FMI,MB86904
Welcome to OpenBIOS v1.0 built on Mar 31 2009 15:36
  Type 'help' for detailed information

[sparc] Booting file 'disk' with parameters ''
Trying disk (/iommu/sbus/espdma/esp/sd@0,0)
Not a bootable ELF image
Not a Linux kernel image
Loading a.out image...
Loaded 7680 bytes
entry point is 0x4000
Jumping to entry point...
SILO Version 1.4.13
boot: 
Uncompressing image...
Loaded kernel version 2.6.18
Loading initial ramdisk (3213705 bytes at 0x3000000 phys, 0x60000000 virt)...
PROMLIB: obio_ranges 1
Booting Linux...
PROMLIB: Sun Boot Prom Version 3 Revision 2
Linux version 2.6.18-6-sparc32 (Debian 2.6.18.dfsg.1-24) (dannf@debian.org) (gcc version 4.1.2 20061115 (prerelease) (Debian 4.1.1-21)) #1 Sat Dec 27 09:13:12 UTC 2008
ARCH: SUN4M
TYPE: SPARCstation 5
Ethernet address: 52:54:0:12:34:56
Boot time fixup v1.6. 4/Mar/98 Jakub Jelinek (jj@ultra.linux.cz). Patching kernel for srmmu[Fujitsu TurboSparc]/iommu
PROM: Built device tree with 21674 bytes of memory.
Power off control detected.
Built 1 zonelists.  Total pages: 31151
Kernel command line: root=/dev/sda2 ro
PID hash table entries: 512 (order: 9, 2048 bytes)
start_kernel(): bug: interrupts were enabled early
Console: colour dummy device 80x25
Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
Memory: 121100k/130124k available (1640k kernel code, 8884k reserved, 404k data, 136k init, 0k highmem)
Mount-cache hash table entries: 512
checking if image is initramfs... it is
Freeing initrd memory: 3138k freed
NET: Registered protocol family 16
IOMMU: impl 0 vers 5 table 0xf3280000[262144 B] map [65536 b]
sbus0: Clock 21.1250 MHz
dma0: Revision 2 
dma1: Revision 0 
NET: Registered protocol family 2
IP route cache hash table entries: 1024 (order: 0, 4096 bytes)
TCP established hash table entries: 4096 (order: 2, 16384 bytes)
TCP bind hash table entries: 2048 (order: 1, 8192 bytes)
TCP: Hash tables configured (established 4096 bind 2048)
TCP reno registered
ioremap: done with statics, switching to malloc
apc: power management initialized
VFS: Disk quotas dquot_6.5.1
Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Initializing Cryptographic API
io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered (default)
Console: switching to colour frame buffer device 128x48
/iommu@0,10000000/sbus@0,10001000/SUNW,tcx@3,800000: TCX at 0:50800000, 8-bit only
ffd76348: ttyS0 at MMIO 0x71100000 (irq = 44) is a zs
Console: ttyS0 (SunZilog zs0)
ffd76348: ttyS1 at MMIO 0x71100004 (irq = 44) is a zs
ffd7657c: Keyboard at MMIO 71000000 (irq = 44) is a zs
ffd7657c: Mouse at MMIO 71000004 (irq = 44) is a zs
Floppy drive(s): fd0 is 1.44M
FDC 0 is a S82078B
RAMDISK driver initialized: 16 RAM disks of 8192K size 1024 blocksize
rtc_sun_init: Registered Mostek RTC driver.
mice: PS/2 mouse device common for all mice
TCP bic registered
NET: Registered protocol family 1
NET: Registered protocol family 17
Freeing unused kernel memory: 136k freed
Loading, please wait...
Begin: Loading essential drivers... ...
SCSI subsystem initialized
esp0: IRQ 36 SCSI ID 7 Clk 40MHz CCYC=25000 CCF=8 TOut 167 NCR53C9XF(espfast)
scsi0 : Sparc ESP100A-FAST
Unable to handle kernel paging request at virtual address fe62f000
tsk->{mm,active_mm}->context = 0000007f
tsk->{mm,active_mm}->pgd = fc014400
              \|/ ____ \|/
              "@'/ ,. \`@"
              /_| \__/ |_\
                 \__U_/
modprobe(771): Oops [#1]
PSR: 04000fc7 PC: fe62f000 NPC: fe62f004 Y: fffffffc    Not tainted
PC: <__scsi_device_lookup_by_target+0x8/0x40 [scsi_mod]>
%G: ffffffff 04000fe0  00000000 044000e0  f0115c18 49ff53a9  f3274000 00000000
%O: f3249400 00000000  f3275a20 f3249484  f3249484 0000000c  f3275980 fe62f204
RPC: <scsi_device_lookup_by_target+0x44/0x74 [scsi_mod]>
%L: 040000e0 fe6362e8  fe6363cc 00000004  00000008 00000000  00000000 0000000a
%I: f3249400 00000000  00000000 00000000  00000000 f9828000  f32759e8 fe635528
Caller[fe635528]: scsi_probe_and_add_lun+0x40/0x9f4 [scsi_mod]
Caller[fe63641c]: __scsi_scan_target+0xa8/0x5a8 [scsi_mod]
Caller[fe63696c]: scsi_scan_channel+0x50/0x74 [scsi_mod]
Caller[fe636a1c]: scsi_scan_host_selected+0x8c/0xd8 [scsi_mod]
Caller[fe61ec80]: esp_sbus_probe+0x9f4/0xae8 [esp]
Caller[f001ba48]: of_device_probe+0x58/0x74
Caller[f01176b4]: driver_probe_device+0x60/0xb8
Caller[f0117814]: __driver_attach+0x70/0xc4
Caller[f0116f9c]: bus_for_each_dev+0x40/0x74
Caller[f0116bec]: bus_add_driver+0x6c/0x134
Caller[f004c86c]: sys_init_module+0x1610/0x1778
Caller[f0011634]: syscall_is_too_hard+0x3c/0x40
Caller[000133b4]: 0x133bc
Instruction DUMP:<1>Unable to handle kernel paging request at virtual address fe62e000
tsk->{mm,active_mm}->context = 0000007f
tsk->{mm,active_mm}->pgd = fc014400
              \|/ ____ \|/
              "@'/ ,. \`@"
              /_| \__/ |_\
                 \__U_/
modprobe(771): Oops [#2]
PSR: 04800fc2 PC: f0012744 NPC: f0030ca0 Y: 00000000    Not tainted
PC: <instruction_dump+0x3c/0x74>
%G: 00000000 f01a5c00  fffffff4 04400fe1  f0030318 f022d9d8  f3274000 00000000
%O: f01a5f78 00000020  000133bc 00000020  f327563c f3275718  f3275668 f0012740
RPC: <instruction_dump+0x38/0x74>
%L: fffffffe fe62f000  fe62f004 fffffffc  04000fc7 00000000  f3274000 fe6467b8
%I: fe62f000 000133bc  00000303 f01a7b30  00000001 f0231c00  f32756d0 f0012898
Caller[f0012898]: die_if_kernel+0xfc/0x11c
Caller[f001ce74]: unhandled_fault+0x90/0x94
Caller[f001d148]: do_sparc_fault+0x28c/0x3e8
Caller[f0011340]: srmmu_fault+0x60/0x68
Caller[fe62f204]: scsi_device_lookup_by_target+0x44/0x74 [scsi_mod]
Caller[fe635528]: scsi_probe_and_add_lun+0x40/0x9f4 [scsi_mod]
Caller[fe63641c]: __scsi_scan_target+0xa8/0x5a8 [scsi_mod]
Caller[fe63696c]: scsi_scan_channel+0x50/0x74 [scsi_mod]
Caller[fe636a1c]: scsi_scan_host_selected+0x8c/0xd8 [scsi_mod]
Caller[fe61ec80]: esp_sbus_probe+0x9f4/0xae8 [esp]
Caller[f001ba48]: of_device_probe+0x58/0x74
Caller[f01176b4]: driver_probe_device+0x60/0xb8
Caller[f0117814]: __driver_attach+0x70/0xc4
Caller[f0116f9c]: bus_for_each_dev+0x40/0x74
Caller[f0116bec]: bus_add_driver+0x6c/0x134
Caller[f004c86c]: sys_init_module+0x1610/0x1778
Caller[f0011634]: syscall_is_too_hard+0x3c/0x40
Caller[000133b4]: 0x133bc
Instruction DUMP: 0280000a  90106378  40007958 <d4060002> 80a42005  24bffff6  852c2002  313c06b5  40007952 
Killed
Done.
Begin: Running /scripts/init-premount ...
Done.
Begin: Mounting root file system... ...
Begin: Running /scripts/local-top ...
Done.
Begin: Waiting for root file system... ...
QEMU: Terminated

Re: [Qemu-devel] SPARC kernel oops with logging

[Blue Swirl]

On 5/5/09, Gabriel Southern <gabriel.southern@gmail.com> wrote:
> Hi,
>
>  When I run qemu-system-sparc with -d in_asm,out_asm the Linux kernel
>  crashes when it tries to initialize the hard drive.  The same hard
>  drive image boots perfectly if I do not include the logging options.
>  The error messages that I receive are shown below.  I'm wondering if
>  the logging is causing some type of acknowledgment to be delayed and
>  this is causing a SCSI operation to timeout.  I've also attached log
>  of the complete console output in case anyone would find it useful.
>  If anyone has ideas about the cause or a possible solution please let
>  me know.

The lines in qemu.log near the crash could be interesting too.

>  %G: ffffffff 04000fe0  00000000 044000e0  f0115c18 49ff53a9  f3274000 00000000

%g0 not equal to zero?

>  %O: f3249400 00000000  f3275a20 f3249484  f3249484 0000000c  f3275980 fe62f204
>  RPC: <scsi_device_lookup_by_target+0x44/0x74 [scsi_mod]>

I guess this means that the call to fe62f000 came from fe62f204, which
is in the same page. Strange.

>  %L: 040000e0 fe6362e8  fe6363cc 00000004  00000008 00000000  00000000 0000000a
>  %I: f3249400 00000000  00000000 00000000  00000000 f9828000  f32759e8 fe635528
>  Caller[fe635528]: scsi_probe_and_add_lun+0x40/0x9f4 [scsi_mod]
>  Caller[fe63641c]: __scsi_scan_target+0xa8/0x5a8 [scsi_mod]
>  Caller[fe63696c]: scsi_scan_channel+0x50/0x74 [scsi_mod]
>  Caller[fe636a1c]: scsi_scan_host_selected+0x8c/0xd8 [scsi_mod]
>  Caller[fe61ec80]: esp_sbus_probe+0x9f4/0xae8 [esp]
>  Caller[f001ba48]: of_device_probe+0x58/0x74
>  Caller[f01176b4]: driver_probe_device+0x60/0xb8
>  Caller[f0117814]: __driver_attach+0x70/0xc4
>  Caller[f0116f9c]: bus_for_each_dev+0x40/0x74
>  Caller[f0116bec]: bus_add_driver+0x6c/0x134
>  Caller[f004c86c]: sys_init_module+0x1610/0x1778
>  Caller[f0011634]: syscall_is_too_hard+0x3c/0x40
>  Caller[000133b4]: 0x133bc
>
>

Re: [Qemu-devel] SPARC kernel oops with logging

[Gabriel Southern]

I was logging the in_asm and out_asm, but I'm not sure what part of
the log corresponds to when the kernel oops occurs.  If anyone has any
suggestions on what I should look for I will try to post it to the
mailing list.

I think that the problem is related to logging in_asm.  I tried
various other combinations of logging options, and the VM runs fine
for any logging option except in_asm (and it also fails with only
in_asm logging).

If anyone else wants to look at the problem, I think it is easy to
duplicate.  In order to rule out problems with what I am working on, I
downloaded the debian_etch_sparc_small.qcow.gz image from here:

http://people.debian.org/~aurel32/qemu/sparc/

and I compiled the latest qemu from the git repository.  When I
included the -d in_asm option the kernel had the same error every time
it boots.

On Tue, May 5, 2009 at 8:29 AM, Blue Swirl <blauwirbel@gmail.com> wrote:
> On 5/5/09, Gabriel Southern <gabriel.southern@gmail.com> wrote:
>> Hi,
>>
>>  When I run qemu-system-sparc with -d in_asm,out_asm the Linux kernel
>>  crashes when it tries to initialize the hard drive.  The same hard
>>  drive image boots perfectly if I do not include the logging options.
>>  The error messages that I receive are shown below.  I'm wondering if
>>  the logging is causing some type of acknowledgment to be delayed and
>>  this is causing a SCSI operation to timeout.  I've also attached log
>>  of the complete console output in case anyone would find it useful.
>>  If anyone has ideas about the cause or a possible solution please let
>>  me know.
>
> The lines in qemu.log near the crash could be interesting too.
>
>>  %G: ffffffff 04000fe0  00000000 044000e0  f0115c18 49ff53a9  f3274000 00000000
>
> %g0 not equal to zero?
>
>>  %O: f3249400 00000000  f3275a20 f3249484  f3249484 0000000c  f3275980 fe62f204
>>  RPC: <scsi_device_lookup_by_target+0x44/0x74 [scsi_mod]>
>
> I guess this means that the call to fe62f000 came from fe62f204, which
> is in the same page. Strange.
>
>>  %L: 040000e0 fe6362e8  fe6363cc 00000004  00000008 00000000  00000000 0000000a
>>  %I: f3249400 00000000  00000000 00000000  00000000 f9828000  f32759e8 fe635528
>>  Caller[fe635528]: scsi_probe_and_add_lun+0x40/0x9f4 [scsi_mod]
>>  Caller[fe63641c]: __scsi_scan_target+0xa8/0x5a8 [scsi_mod]
>>  Caller[fe63696c]: scsi_scan_channel+0x50/0x74 [scsi_mod]
>>  Caller[fe636a1c]: scsi_scan_host_selected+0x8c/0xd8 [scsi_mod]
>>  Caller[fe61ec80]: esp_sbus_probe+0x9f4/0xae8 [esp]
>>  Caller[f001ba48]: of_device_probe+0x58/0x74
>>  Caller[f01176b4]: driver_probe_device+0x60/0xb8
>>  Caller[f0117814]: __driver_attach+0x70/0xc4
>>  Caller[f0116f9c]: bus_for_each_dev+0x40/0x74
>>  Caller[f0116bec]: bus_add_driver+0x6c/0x134
>>  Caller[f004c86c]: sys_init_module+0x1610/0x1778
>>  Caller[f0011634]: syscall_is_too_hard+0x3c/0x40
>>  Caller[000133b4]: 0x133bc
>>
>>
>

Re: [Qemu-devel] SPARC kernel oops with logging

[Blue Swirl]

On 5/6/09, Gabriel Southern <gabriel.southern@gmail.com> wrote:
> I was logging the in_asm and out_asm, but I'm not sure what part of
>  the log corresponds to when the kernel oops occurs.  If anyone has any
>  suggestions on what I should look for I will try to post it to the
>  mailing list.
>
>  I think that the problem is related to logging in_asm.  I tried
>  various other combinations of logging options, and the VM runs fine
>  for any logging option except in_asm (and it also fails with only
>  in_asm logging).
>
>  If anyone else wants to look at the problem, I think it is easy to
>  duplicate.  In order to rule out problems with what I am working on, I
>  downloaded the debian_etch_sparc_small.qcow.gz image from here:
>
>  http://people.debian.org/~aurel32/qemu/sparc/
>
>  and I compiled the latest qemu from the git repository.  When I
>  included the -d in_asm option the kernel had the same error every time
>  it boots.
>
>
>  On Tue, May 5, 2009 at 8:29 AM, Blue Swirl <blauwirbel@gmail.com> wrote:
>  > On 5/5/09, Gabriel Southern <gabriel.southern@gmail.com> wrote:
>  >> Hi,
>  >>
>  >>  When I run qemu-system-sparc with -d in_asm,out_asm the Linux kernel
>  >>  crashes when it tries to initialize the hard drive.  The same hard
>  >>  drive image boots perfectly if I do not include the logging options.
>  >>  The error messages that I receive are shown below.  I'm wondering if
>  >>  the logging is causing some type of acknowledgment to be delayed and
>  >>  this is causing a SCSI operation to timeout.  I've also attached log
>  >>  of the complete console output in case anyone would find it useful.
>  >>  If anyone has ideas about the cause or a possible solution please let
>  >>  me know.
>  >
>  > The lines in qemu.log near the crash could be interesting too.
>  >
>  >>  %G: ffffffff 04000fe0  00000000 044000e0  f0115c18 49ff53a9  f3274000 00000000
>  >
>  > %g0 not equal to zero?
>  >
>  >>  %O: f3249400 00000000  f3275a20 f3249484  f3249484 0000000c  f3275980 fe62f204
>  >>  RPC: <scsi_device_lookup_by_target+0x44/0x74 [scsi_mod]>
>  >
>  > I guess this means that the call to fe62f000 came from fe62f204, which
>  > is in the same page. Strange.
>  >
>  >>  %L: 040000e0 fe6362e8  fe6363cc 00000004  00000008 00000000  00000000 0000000a
>  >>  %I: f3249400 00000000  00000000 00000000  00000000 f9828000  f32759e8 fe635528
>  >>  Caller[fe635528]: scsi_probe_and_add_lun+0x40/0x9f4 [scsi_mod]
>  >>  Caller[fe63641c]: __scsi_scan_target+0xa8/0x5a8 [scsi_mod]
>  >>  Caller[fe63696c]: scsi_scan_channel+0x50/0x74 [scsi_mod]
>  >>  Caller[fe636a1c]: scsi_scan_host_selected+0x8c/0xd8 [scsi_mod]
>  >>  Caller[fe61ec80]: esp_sbus_probe+0x9f4/0xae8 [esp]
>  >>  Caller[f001ba48]: of_device_probe+0x58/0x74
>  >>  Caller[f01176b4]: driver_probe_device+0x60/0xb8
>  >>  Caller[f0117814]: __driver_attach+0x70/0xc4
>  >>  Caller[f0116f9c]: bus_for_each_dev+0x40/0x74
>  >>  Caller[f0116bec]: bus_add_driver+0x6c/0x134
>  >>  Caller[f004c86c]: sys_init_module+0x1610/0x1778
>  >>  Caller[f0011634]: syscall_is_too_hard+0x3c/0x40
>  >>  Caller[000133b4]: 0x133bc
>  >>
>  >>
>  >
>

I think this patch should fix the problem.

Sparc disassembler wants to check previous addresses for some stuff
and this may actually cause faults if the address is close to page
start, because of the function used for the memory access.

Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
---
 disas.c |    5 +----
 1 files changed, 1 insertions(+), 4 deletions(-)

diff --git a/disas.c b/disas.c
index 37f7433..6ed31e3 100644
--- a/disas.c
+++ b/disas.c
@@ -33,10 +33,7 @@ target_read_memory (bfd_vma memaddr,
                     int length,
                     struct disassemble_info *info)
 {
-    int i;
-    for(i = 0; i < length; i++) {
-        myaddr[i] = ldub_code(memaddr + i);
-    }
+    cpu_memory_rw_debug(cpu_single_env, memaddr, myaddr, length, 0);
     return 0;
 }

-- 
1.6.2.4

Re: [Qemu-devel] SPARC kernel oops with logging

[Gabriel Southern]

Thanks, this patch does seem to have fixed the problem for me.

-Gabriel

>
> I think this patch should fix the problem.
>
> Sparc disassembler wants to check previous addresses for some stuff
> and this may actually cause faults if the address is close to page
> start, because of the function used for the memory access.
>
> Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
> ---
>  disas.c |    5 +----
>  1 files changed, 1 insertions(+), 4 deletions(-)
>
> diff --git a/disas.c b/disas.c
> index 37f7433..6ed31e3 100644
> --- a/disas.c
> +++ b/disas.c
> @@ -33,10 +33,7 @@ target_read_memory (bfd_vma memaddr,
>                     int length,
>                     struct disassemble_info *info)
>  {
> -    int i;
> -    for(i = 0; i < length; i++) {
> -        myaddr[i] = ldub_code(memaddr + i);
> -    }
> +    cpu_memory_rw_debug(cpu_single_env, memaddr, myaddr, length, 0);
>     return 0;
>  }
>
> --
> 1.6.2.4
>

Re: [Qemu-devel] SPARC kernel oops with logging

[Blue Swirl]

On 5/7/09, Gabriel Southern <gabriel.southern@gmail.com> wrote:
> Thanks, this patch does seem to have fixed the problem for me.

Committed, thanks for testing.