Re: ARAnyM VMs with Debian hanging at 100% CPU usage
Dixi quod…
>I’ve got ARAnyM VMs hanging at 100% CPU, no network response any more,
Uh, it gets more interesting. Please, if any ARAnyM, Linux or Debian
developer has got an idea…
I thought I just had the hang during an update. Resetted the VM, then
tried the update again. The following is a “screenshot” of the split-
screen terminal (GNU screen) at freeze point (108x33):
Reading package lists...
Building dependency tree...
Reading state information... Starting
Starting 2
Done
The following packages will be upgraded:
dpkg libc-bin libc-dev-bin libc6 libc6-dev libdb5.1 libxml2 multiarch-support
8 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Need to get 11.5 MB of archives.
After this operation, 278 kB of additional disk space will be used.
Get:1 http://ftp.debian-ports.org/debian/ unstable/main dpkg m68k 1.16.8 [2293 kB]
Get:2 http://www.freewrt.org/~tg/debs68k/ sid/main libdb5.1 m68k 5.1.29-5 [632 kB]
Get:3 http://ftp.debian-ports.org/debian/ unstable/main libc6-dev m68k 2.13-35 [2140 kB]
0 -
root@aranym:~ # cd /var/cache/pbuilder/build/cow.1393/var/l
lib/ local/ lock/ log/
root@aranym:~ # cd /var/cache/pbuilder/build/cow.1393/var/lib/apt/lists/
root@aranym:...der/build/cow.1393/var/lib/apt/lists # pax -rw -pe f* w* /var/lib/apt/lists/;cd;agus -f
+ apt-get update
1 -
aranym 1.65 1.07 0.55 Thu 26.07.2012 08:17 [0 -] 1 -
(Explanation: the upper tab has 'eatmydata cowbuilder --update' running;
in the lower tab I copy the APT repository lists it has downloaded into
the live system and then run 'agus -f', which for our purpose is 'set -x;
apt-get update'.)
This is the stdout+stderr of the VM:
Running Aranym on X11: :0.0
ARAnyM 0.9.13
Using config file: 'aranym.config.x11'
Could not open joystick 0
ARAnyM RTC Timer: /dev/rtc: Device or resource busy
ARAnyM LILO: Error loading ramdisk 'root.bin'
[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Linux version 3.2.0-3-atari (Debian 3.2.21-3) (debian-kernel@lists.debian.org) (gcc version 4.6.3 (Debian 4.6.3-7+m68k.2) ) #1 Sat Jun 30 06:00:58 UTC 2012
[ 0.000000] console [debug0] enabled
[ 0.000000] Atari hardware found: VIDEL STDMA-SCSI ST_MFP YM2149 PCM CODEC DSP56K SCC ANALOG_JOY Blitter tried to read byte from register ff8a00 at 007232
BLITTER IDE TT_CLK FDC_SPEED
[ 0.000000] NatFeats found (ARAnyM, 1.0)
[ 0.000000] On node 0 totalpages: 3584
[ 0.000000] free_area_init_node: node 0, pgdat 0037f7b0, node_mem_map 004b4000
[ 0.000000] DMA zone: 32 pages used for memmap
[ 0.000000] DMA zone: 0 pages reserved
[ 0.000000] DMA zone: 3552 pages, LIFO batch:0
[ 0.000000] On node 1 totalpages: 196608
[ 0.000000] free_area_init_node: node 1, pgdat 0038015c, node_mem_map 004d8090
[ 0.000000] DMA zone: 1728 pages used for memmap
[ 0.000000] DMA zone: 0 pages reserved
[ 0.000000] DMA zone: 194880 pages, LIFO batch:31
[ 0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[ 0.000000] pcpu-alloc: [0] 0
[ 0.000000] Built 2 zonelists in Zone order, mobility grouping on. Total pages: 198432
[ 0.000000] Kernel command line: root=/dev/nfhd8p1 console=tty debug=par devtmpfs.mount=1 video=atafb:vga2 BOOT_IMAGE=vmlinux
[ 0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Memory: 787060k/787060k available (2756k kernel code, 10864k data, 112k init)
[ 0.000000] NR_IRQS:72
[ 0.000000] Console: colour dummy device 80x25
[ 0.000000] console [tty0] enabled
[ 0.010000] Calibrating delay loop... 94.61 BogoMIPS (lpj=473088)
[ 0.100000] pid_max: default: 32768 minimum: 301
[ 0.100000] Security Framework initialized
[ 0.100000] AppArmor: AppArmor disabled by boot time parameter
[ 0.100000] Mount-cache hash table entries: 512
[ 0.100000] Initializing cgroup subsys cpuacct
[ 0.100000] Initializing cgroup subsys memory
[ 0.100000] Initializing cgroup subsys devices
[ 0.100000] Initializing cgroup subsys freezer
[ 0.100000] Initializing cgroup subsys blkio
[ 0.110000] devtmpfs: initialized
[ 0.110000] print_constraints: dummy:
[ 0.110000] NET: Registered protocol family 16
[ 0.130000] bio: create slab <bio-0> at 0
[ 0.140000] SCSI subsystem initialized
[ 0.180000] NET: Registered protocol family 2
[ 0.180000] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 0.190000] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[ 0.210000] TCP bind hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.220000] TCP: Hash tables configured (established 131072 bind 65536)
[ 0.220000] TCP reno registered
[ 0.220000] UDP hash table entries: 512 (order: 1, 8192 bytes)
[ 0.220000] UDP-Lite hash table entries: 512 (order: 1, 8192 bytes)
[ 0.220000] NET: Registered protocol family 1
[ 0.230000] nfhd8: found device with 20971440 blocks (512 bytes)
[ 0.230000] nfhd8: AHDI p1 p2
[ 0.230000] nfeth: API 5
[ 0.240000] eth0: nfeth addr:192.168.0.1 (192.168.0.2) HWaddr:52:54:00:22:00:01
[ 0.240000] audit: initializing netlink socket (disabled)
[ 0.240000] type=2000 audit(1340698084.240:1): initialized
[ 0.240000] VFS: Disk quotas dquot_6.5.2
[ 0.240000] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.250000] msgmni has been set to 1537
[ 0.250000] alg: No test for stdrng (krng)
[ 0.250000] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[ 0.250000] io scheduler noop registered
[ 0.250000] io scheduler deadline registered
[ 0.250000] io scheduler cfq registered (default)
[ 0.250000] atafb_init: start
[ 0.250000] atafb_init: initializing Falcon hw
[ 0.250000] atafb: screen_base 00b9b000 real_screen_base 00b9b000 screen_len 81920
[ 0.260000] Determined 640x480, depth 1
[ 0.260000] virtual 640x1024
[ 0.270000] Console: switching to mono frame buffer device 80x30
[ 0.280000] fb0: frame buffer device, using 80K of video memory
[ 0.280000] Non-volatile memory driver v1.3
[ 0.290000] Atari floppy driver: max. HD, track buffering
[ 0.290000] Probing floppy drive(s):
[ 0.290000] fd0
[ 0.300000] Uniform Multi-Platform E-IDE driver
[ 0.320000] ide: Falcon IDE controller
[ 0.340000] Probing IDE interface ide0...
[ 0.720000] hda: Master, ATA DISK drive
[ 1.820000] ide0 at 0xfff00000 on irq 15 (serialized)
[ 1.820000] ide-gd driver 1.18
[ 1.840000] hda: max request size: 128KiB
[ 1.840000] hda: 20971440 sectors (10737 MB) w/256KiB Cache, CHS=20805/16/63
[ 1.880000] hda: AHDI hda1 hda2
[ 1.890000] ide-cd driver 5.00
[ 1.900000] scsi0: options CAN_QUEUE=8 CMD_PER_LUN=1 SCAT-GAT=0 TAGGED-QUEUING=no HOSTID=7 generic options AUTOSENSE REAL DMA SCSI-2 TAGGED QUEUING generic release=7
[ 1.940000] scsi0 : Atari native SCSI
[ 1.950000] blk_queue_max_segments: set to minimum 1
[ 2.210000] blk_queue_max_segments: set to minimum 1
[ 2.220000] mousedev: PS/2 mouse device common for all mice
[ 2.470000] input: Atari Keyboard as /devices/virtual/input/input0
[ 2.480000] input: Atari mouse as /devices/virtual/input/input1
[ 2.740000] blk_queue_max_segments: set to minimum 1
[ 2.990000] blk_queue_max_segments: set to minimum 1
[ 3.250000] blk_queue_max_segments: set to minimum 1
[ 3.260000] rtc-generic rtc-generic: rtc core: registered rtc-generic as rtc0
[ 3.510000] blk_queue_max_segments: set to minimum 1
[ 3.520000] TCP cubic registered
[ 3.540000] NET: Registered protocol family 17
[ 3.540000] NET: Registered protocol family 15
[ 3.560000] registered taskstats version 1
[ 3.580000] scsi: waiting for bus probes to complete ...
[ 3.830000] blk_queue_max_segments: set to minimum 1
[ 4.140000] rtc-generic rtc-generic: setting system clock to 2012-07-26 08:08:08 UTC (1343290088)
[ 4.160000] EXT4-fs (nfhd8p1): mounting ext3 file system using the ext4 subsystem
[ 4.180000] EXT4-fs (nfhd8p1): INFO: recovery required on readonly filesystem
[ 4.200000] EXT4-fs (nfhd8p1): write access will be enabled during recovery
[ 10.660000] EXT4-fs (nfhd8p1): orphan cleanup on readonly fs
[ 10.660000] EXT4-fs (nfhd8p1): ext4_orphan_cleanup: deleting unreferenced inode 981142
[ 10.750000] EXT4-fs (nfhd8p1): ext4_orphan_cleanup: deleting unreferenced inode 654293
[ 10.790000] EXT4-fs (nfhd8p1): ext4_orphan_cleanup: deleting unreferenced inode 654433
[ 10.830000] EXT4-fs (nfhd8p1): ext4_orphan_cleanup: deleting unreferenced inode 1030237
[ 10.860000] EXT4-fs (nfhd8p1): 4 orphan inodes deleted
[ 10.880000] EXT4-fs (nfhd8p1): recovery complete
[ 10.900000] EXT4-fs (nfhd8p1): mounted filesystem with ordered data mode. Opts: (null)
[ 10.930000] VFS: Mounted root (ext3 filesystem) readonly on device 254:129.
[ 10.970000] devtmpfs: mounted
[ 19.180000] udevd[134]: starting version 175
Detected scancode offset = 8 (key: 'a' with scancode $26)
[ 25.680000] Adding 1989620k swap on /dev/nfhd8p2. Priority:-1 extents:1 across:1989620k
[ 26.090000] EXT4-fs (nfhd8p1): re-mounted. Opts: (null)
[ 27.510000] EXT4-fs (nfhd8p1): re-mounted. Opts: errors=remount-ro
[ 47.610000] ------------[ cut here ]------------
[ 47.620000] WARNING: at /tmp/buildd/linux-3.2.21/kernel/irq/handle.c:130 handle_irq_event_percpu+0x130/0x13e()
[ 47.640000] irq 3 handler nfeth_interrupt+0x0/0x190 enabled interrupts
[ 47.660000] Modules linked in: evdev
[ 47.680000] Call Trace: [<000304ae>] warn_slowpath_common+0x48/0x6a
[ 47.700000] [<000304bc>] warn_slowpath_common+0x56/0x6a
[ 47.700000] [<00030548>] warn_slowpath_fmt+0x2a/0x32
[ 47.720000] [<00066696>] handle_irq_event_percpu+0x130/0x13e
[ 47.730000] [<002ac106>] printk+0x0/0x18
[ 47.740000] [<00066696>] handle_irq_event_percpu+0x130/0x13e
[ 47.760000] [<0000a338>] nfeth_interrupt+0x0/0x190
[ 47.770000] [<000666c4>] handle_irq_event+0x20/0x2c
[ 47.780000] [<00065ecc>] generic_handle_irq+0x2c/0x3a
[ 47.820000] [<00002940>] do_IRQ+0x20/0x32
[ 47.840000] [<00002766>] auto_irqhandler_fixup+0x4/0x6
[ 47.860000]
[ 47.860000] ---[ end trace 76d03722973df049 ]---
[ 49.370000] NET: Registered protocol family 10
[ 60.040000] eth0: no IPv6 routers present
[ 596.120000] BUG: soft lockup - CPU#0 stuck for 23s! [https:1672]
[ 596.120000] Modules linked in: ipv6 evdev
[ 596.120000]
[ 596.120000] Format 00 Vector: 0114 PC: 00085602 Status: 2300 Tainted: G W
[ 596.120000] ORIG_D0: ffffffff D0: 00000000 A2: 2a57f510 A1: 2a40b6c8
[ 596.120000] A0: 00c9d170 D5: 00000000 D4: 2a649fcc
[ 596.120000] D3: 2a53c320 D2: 8001fda8 D1: 2a612000
Any help appreciated. I’m not assigning a culprit, just want this
solved. It seems to have popped up (more?) with the backport of
the GCC atomics stuff, which uses the syscall. That’s all I know.
TIA,
//mirabilos
--
08:05⎜<XTaran:#grml> mika: Does grml have an tool to read Apple
⎜ System Log (asl) files? :)
08:08⎜<ft:#grml> yeah. /bin/rm. ;) 08:09⎜<mrud:#grml> hexdump -C
08:31⎜<XTaran:#grml> ft, mrud: *g*
Reply to: