VMware
1 2 Previous Next 28 Replies Last post: Apr 4, 2006 5:43 PM by petr  

Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal error posted: Aug 12, 2005 5:21 PM

Click to view JPV's profile Novice
JPV
24 posts since
Jun 16, 2005
I have VMware Workstation 5 running on a host OS of CentOS-4.1 (RHEL 4.1 rebuild, see www.centos.org). Host OS is a *minimal* install, using Xfce4 and as little else as I could manage. SELinux is disabled.

For the second time now, I've crashed as follows. The first time was a few weeks ago and I ignored it and rebooted, so no info there. I *think* I was running a Windows WM that time too though. (Damn Windows, can even get it stable when running it on Linux! :-) )

This time I was running 2 Win2K server VMs (linked clones) with 3 other (various Linux) VMs paused. The box is a plain Dell Optiplex GX-260 P4-500 with 1G RAM and 80G IDE. It is company owned and I haven't messed with it (i.e. no overclocking). The machine is on an old Compaq PS/2 KVM, so no USB BS. The Windows VMs are fully patched (ironically I was testing a patch management tool in them).
VMware tools are installed on the 2 Windows VMs and they are using auto mouse-grab. I am not running full-screen.

A soft reboot of the host machine fixed the problem, for now. Naturally, on reboot an fsck was forced on that partition, and it completed with a couple of minor inod complaints.

I can't try another host as I don't have anything laying around with the hosepower needed. But up until recently that box was a Win2KPro workstation that worked fine except that it had Windows on it.

Possibly related to the following, though I have NOT been able to tie it to any mouse movement (haven't tried very hard either):
http://www.vmware.com/community/thread.jspa?threadID=17535
http://www.vmware.com/community/thread.jspa?threadID=7598
http://www.linuxquestions.org/questions/history/342887
http://www.webservertalk.com/archive235-2004-6-285876.html
http://ist.uwaterloo.ca/~kscully/crow.html

Symptom:
Dialog box: 'Operation on file "foo.vmdk" failed (Read-only files system.) Choose retry to attempt again… [Abort] [Continue] [Retry]'

Dmesg begins " start_transaction: Journal has aborted" then has 224: "EXT3-fs error (device hda4) in start_transaction: Journal has aborted"

Console had: "hostname kernel: journal_get_undo_access: No memory for committed data"

/var/log/messages has nothing relevant.

Running everything under non-root user. VMware was only running for 2 days or so, nothing in the vmware.log that looks relevant, head/tail as follows:

/home/jp/vmware/Windows_2000_Server# head vmware.log
Aug 11 00:41:22: vmx| Log for VMware Workstation pid=31004 version=5.0.0 build=build-13124 option=Release
Aug 11 00:41:22: vmx| Command line: "/usr/lib/vmware/bin/vmware-vmx" "-@" "pipe=/tmp/vmware-jp/vmx0e8fab5e213e2683;vm0e8fab5e213e2683" "/home/jp/vmware/Windows_2000_Server/Windows_2000_Server.vmx"
Aug 11 00:41:22: vmx| UI Connecting to pipe '/tmp/vmware-jp/vmx0e8fab5e213e2683' with user '(null)'
Aug 11 00:41:22: vmx| pcpu #0 CPUID numEntries=2 GenuntelineI
Aug 11 00:41:22: vmx| pcpu #0 CPUID version=0xf27 id1.edx=0xbfebfbff id1.ecx=0x400 id1.ebx=0x20809
Aug 11 00:41:22: vmx| pcpu #0 CPUID id80.eax=80000004 id81.edx=0x0 id81.ecx=0x0
Aug 11 00:41:22: vmx| CPUID id1.edx: 0xbfebfbff id1.ecx: 0x400 id81.edx: 0 id81.ecx: 0
Aug 11 00:41:22: vmx| changing directory to /home/jp/vmware/Windows_2000_Server/.
Aug 11 00:41:22: vmx| Config file: /home/jp/vmware/Windows_2000_Server/Windows_2000_Server.vmx
Aug 11 00:41:22: vmx| VMXVmdbCbVmVmxExecState: Exec state change requested to state poweredOn without reset

/home/jp/vmware/Windows_2000_Server# tail vmware.log
Aug 11 01:54:23: vmx| SCSI0:0: Command WRITE(10) took 6.118 seconds (ok)
Aug 11 01:54:31: vmx| SCSI0:0: Command WRITE(10) took 2.540 seconds (ok)
Aug 11 01:54:31: vmx| SCSI0:0: Command WRITE(10) took 2.606 seconds (ok)
Aug 11 01:56:47: vmx| SCSI0:0: Command WRITE(10) took 1.219 seconds (ok)
Aug 11 01:56:47: vmx| SCSI0:0: Command WRITE(10) took 1.379 seconds (ok)
Aug 11 01:56:47: vmx| SCSI0:0: Command WRITE(10) took 1.501 seconds (ok)
Aug 11 06:59:12: vmx| DISKLIB-LIB :numIOs = 50000 numMergedIOs = 2560 numSplitIOs = 1565
Aug 11 23:18:39: vmx| SCSI0:0: Command WRITE(10) took 1.221 seconds (ok)
Aug 12 00:41:21: vmx| LICENSE using: '/home/jp/.vmware/license.ws.5.0'
Aug 12 01:16:22: vmx| DISKLIB-LIB :numIOs = 100000 numMergedIOs = 4150 numSplitIOs = 3215

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

1. Aug 16, 2005 3:09 PM in response to: JPV
Click to view JPV's profile Novice
JPV
24 posts since
Jun 16, 2005
The same thing just happened again. The only difference this time is that I thought to grab output from top as well:

top - 18:09:39 up 3 days, 21:56, 3 users, load average: 0.25, 0.37, 0.36
Tasks: 72 total, 2 running, 70 sleeping, 0 stopped, 0 zombie
Cpu(s): 2.7% us, 11.7% sy, 0.0% ni, 85.7% id, 0.0% wa, 0.0% hi, 0.0% si
Mem: 1034344k total, 1025912k used, 8432k free, 4752k buffers
Swap: 200804k total, 66304k used, 134500k free, 723048k cached

Any clues anyone!?!

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

2. Aug 18, 2005 11:02 AM in response to: JPV
Click to view petr's profile Champion
petr
7,218 posts since
Jul 10, 2003
Post 'dmesg' from host when this happens. It has nothing to do with guest, VMware just wants stable I/O subsystem, and your host remounts harddisk read-only when it sees someone really wants to read & write files a lot...

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

3. Aug 19, 2005 3:33 AM in response to: JPV
Click to view mattlav's profile Novice
mattlav
12 posts since
Dec 18, 2004
Another thing to check would be the SMART status of the drive. The only time that I have had the system remount RO has been when the disk is about to fail. If that drive has about had it then you will see the failures in the SMART output and can grab the data fast.

Matthew

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

4. Aug 19, 2005 11:39 AM in response to: JPV
Click to view sacolcor's profile Lurker
sacolcor
3 posts since
Aug 19, 2005
I have also had this crash multiple times, running CentOS-4.1 hosting WinXPSP2. It seems to be most common during heavy disk I/O, particularly when installing large service packs. The dmesg is the same as the one JPV noted.

This would seem to be a serious problem; it's causing filesystem corruption on the host (and probably the guest, too). And if it's happening on CentOS4, RHEL4 is probably similarly affected.

petr: You indicated that the host "remounts harddisk read-only when it sees someone really wants to read & write files a lot..." Could you elaborate a bit? I don't see how that could be considered correct behavior.

Thanks!

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

5. Aug 22, 2005 5:42 AM in response to: sacolcor
Click to view petr's profile Champion
petr
7,218 posts since
Jul 10, 2003
It is not correct behavior, but it is bug of your *host*, VMware only triggers it because it needs huge I/O bandwidth for guest OS.

BTW, I have no idea what dmesg JPV noted you talk about. I see no 'dmesg' output anywhere. /var/log/messages of course won't show anything - if you remount disk read-only, there is no way how to update /var/log/messages. You must do 'dmesg' when disk is remounted read-only, and write text by hand down to the paper...

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

6. Aug 22, 2005 10:44 AM in response to: petr
Click to view sacolcor's profile Lurker
sacolcor
3 posts since
Aug 19, 2005
The line I was referring to was:

Dmesg begins " start_transaction: Journal has aborted" then has 224: "EXT3-fs error (device hda4) in start_transaction: Journal has aborted"

You indicate that this is a known bug for the Linux kernel...can you provide a link to a bug entry or mailing list record where we can get more information?

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

7. Aug 22, 2005 10:53 AM in response to: sacolcor
Click to view petr's profile Champion
petr
7,218 posts since
Jul 10, 2003
Real error is before this message... You need 'dmesg -s131072' or something like that to find real cause. First message is truncated at the beginning because 'EXT3-fs error (device hda4) in' did not fit to the dmesg buffer size you are using.

Search on google for 'in start_transaction: journal has aborted' returns over 600 hits... I have no idea which particular instance you are hitting until you can provide all error messages. If you cannot find it with 'dmesg -s131072', you may have to use serial console or rebuild your kernel with bigger dmesg buffer or run netconsole to log messages over network to some other system.

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

8. Aug 22, 2005 11:15 AM in response to: petr
Click to view sacolcor's profile Lurker
sacolcor
3 posts since
Aug 19, 2005
Will try that the next time this happens.

I suspect that this console message might be the original error, or close to it:
"<hostname> kernel: journal_get_undo_access: No memory for committed data".

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

9. Aug 22, 2005 4:54 PM in response to: sacolcor
Click to view petr's profile Champion
petr
7,218 posts since
Jul 10, 2003
Yes, it probably is original error source. You've run out of physical memory. Add more memory, run smaller VMs, or configure system for more agressive swapping and releasing memory. First two are obvious, third one can be configured by /proc/sys/vm/swappiness, /proc/sys/vm/min_free_kbytes (and partially by /proc/sys/vm/lowmem_reserve_ratio). Bigger value you put to 'min_free_kbytes', the better. For start I would try double current value. 'swappiness' is by default 60, you may try 70 or maybe even bigger value (100 is max).

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

10. Sep 2, 2005 1:25 PM in response to: JPV
Click to view JPV's profile Novice
JPV
24 posts since
Jun 16, 2005
I've had a couple more crashes since I last posted, but have not had one in 11+ days, while running only 1 VM (W2K). I've only crashed when running 2 or more Windows VMs, so I'll fire up another and wait for a crash. Not sure about heavy disk IO though, VMs were mostly sitting there doing not much of anything during previous crashes.

Re: SMART, it was not running. I checked out the excellent article on this topic at http://www.linuxjournal.com/article/6983 and fired it up. Great tip!

Re: Memory, have 1G phys, running 2 VMs with 256M each, see top output above in http://www.vmware.com/community/thread.jspa?threadID=20690&messageID=248349#248349. Also running a bare minimum Xfce4 with virtually nothing else, expressly to save resources for VMs instead of host.

Was not familiar with /proc/sys/vm/swappiness, it is at the default of 60. But given that I am being quite conservative with memory (IMOHO), should this really matter? Could there be some kind of memory leak when VMware has to handle >1 Windows VM, with associated auto mouse-grab?

FYI, according to VMW Help, Check for Updates, there aren't any. I'm running Workstation 5.0.0 build 13124 on (CentOS/RHEL) kernel 2.6.9-5.0.5.EL.

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

11. Sep 2, 2005 4:16 PM in response to: JPV
Click to view petr's profile Champion
petr
7,218 posts since
Jul 10, 2003
Memory is used also by disk caches, and it can happen that ext3 needs free memory when memory is full of dirty pages with VM & their vmdk files, so no reasonable amount can be freeed at this moment, without doing I/O. And I/O cannot be done as all this lives on one filesystem :-( Increasing swappiness should force host to start writting dirty pages out sooner.

No application should be able to cause problem you see on correct kernel - kernel should start swapping long ago, and if you run out of both physical memory and swap, it should have killed offending application long ago, but not destroy/dismount/damage filesystem. But from your messages it seems like that you did not run out of virtual memory, just kernel tried to be smart about writting data to disk, and it was so smart that when it decided to write them out, it was too late...

You might want to determine what's your device with problem (say /dev/sda1), run 'tune2fs -l /dev/sda1' to find journal inode number (usually 8), and then run [code]echo 'stat <8>' | /sbin/debugfs -f - /dev/sda1[/code] to find journal size (default is 32MB).

If it will look too small, you may want to use tune2fs to remove journal from ext3 (it becomes ext2... 'tune2fs -O ^has_journal /dev/sda1') and add bigger one to the filesystem ('tune2fs -J size=<size you want> -j /dev/sda1'). Keep rescue CD near computer as tune2fs -O ^has_journal will probably require reboot, and it is possible that you have kernel without ext2 support, so maybe you'll have to run second tune2fs from installer's rescue session.

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

12. Sep 2, 2005 5:17 PM in response to: petr
Click to view JPV's profile Novice
JPV
24 posts since
Jun 16, 2005
I see I should have mentioned I have 3 partitions, /boot, / and /data with all the VMW stuff in /data. /var is symlinked into /data/var (I chose sizes poorly). In all crashes, only /data was affected and it does have a 32M journal. System itself was fine, but VMW was very unhappy to be suddenly living in read-only land.

I will try your tune2fs suggestions after next crash. Thanks for all your help on this!

[ringo:root /dev/pts/0]
/root# echo 'stat <8>' | /sbin/debugfs -f - /dev/hda4
debugfs 1.35 (28-Feb-2004)
debugfs: stat <8>
Inode: 8 Type: regular Mode: 0600 Flags: 0x0 Generation: 0
User: 0 Group: 0 Size: 33554432
File ACL: 0 Directory ACL: 0
Links: 1 Blockcount: 65616
Fragment: Address: 0 Number: 0 Size: 0
ctime: 0x42b1af7d -- Thu Jun 16 12:57:33 2005
atime: 0x00000000 -- Wed Dec 31 19:00:00 1969
mtime: 0x42b1af7d -- Thu Jun 16 12:57:33 2005
BLOCKS:
(0-11):1550-1561, (IND):1562, (12-1035):1563-2586, (DIND):2587, (IND):2588, (1036-2059):2589-3612, (IND)
:3613, (2060-3083):3614-4637, (IND):4638, (3084-4107):4639-5662, (IND):5663, (4108-5131):5664-6687, (IND
):6688, (5132-6155):6689-7712, (IND):7713, (6156-7179):7714-8737, (IND):8738, (7180-8192):8739-9751
TOTAL: 8202

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

13. Sep 6, 2005 11:52 PM in response to: petr
Click to view JPV's profile Novice
JPV
24 posts since
Jun 16, 2005
OK, it crashed again, running one W2K and two Linux (cAos-2 and Debian Sarge) VMs! I also have a Linspire, cAos-2 and W2K VM paused. All the same symptoms as above. But one point, I lied about assigned memory--the Windows boxes have 384M RAM each (though I don't remember doing that). I did confirm that each of the Linux VMs has 256M (recall 1G physical RAM and about 200M swap, not sure what I was thinking there). And this time, I am sure I was doing some disk IO (apt-get install samba rsync apache).

I was and am logged into the host via SSH, which was unaffected since it's only /data that is toast, / is fine. I got the following console message, then did the checks as requested (I think).

In the interests of changing only one thing at a time, I've added "echo 90 > /proc/sys/vm/swappiness" to /etc/rc.local. I frankly picked that one as it's easier than messing with tune2fs. Here we go again…


Diagnostics
=========
Message from syslogd@ringo at Wed Sep 7 02:18:51 2005 ...
ringo kernel: journal_get_undo_access: No memory for committed data

[ringo:root /dev/pts/0]
/tmp# top
top - 02:23:55 up 18 days, 22:50, 3 users, load average: 0.13, 0.52, 0.87
Tasks: 74 total, 2 running, 72 sleeping, 0 stopped, 0 zombie
Cpu(s): 3.7% us, 9.0% sy, 0.0% ni, 87.3% id, 0.0% wa, 0.0% hi, 0.0% si
Mem: 1034344k total, 1025488k used, 8856k free, 3428k buffers
Swap: 200804k total, 68316k used, 132488k free, 725288k cached
<snip>

[ringo:root /dev/pts/0]
/tmp# dmesg | head -5
start_transaction: Journal has aborted
EXT3-fs error (device hda4) in start_transaction: Journal has aborted
EXT3-fs error (device hda4) in start_transaction: Journal has aborted
EXT3-fs error (device hda4) in start_transaction: Journal has aborted
EXT3-fs error (device hda4) in start_transaction: Journal has aborted

[ringo:root /dev/pts/0]
/tmp# dmesg | tail -5
EXT3-fs error (device hda4) in start_transaction: Journal has aborted
EXT3-fs error (device hda4) in start_transaction: Journal has aborted
EXT3-fs error (device hda4) in start_transaction: Journal has aborted
EXT3-fs error (device hda4) in start_transaction: Journal has aborted
EXT3-fs error (device hda4) in start_transaction: Journal has aborted

[ringo:root /dev/pts/0]
/tmp# dmesg > dmesg-2005-09-07

[ringo:root /dev/pts/0]
/tmp# wc -l dmesg-2005-09-07
225 dmesg-2005-09-07

[ringo:root /dev/pts/0]
/tmp# smartctl -a /dev/hda
smartctl version 5.33 [i686-redhat-linux-gnu] Copyright (C) 2002-4 Bruce Allen
<snip>
Local Time is: Wed Sep 7 02:32:36 2005 EDT
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED
<snip>
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME FLAG VALUE WORST THRESH TYPE UPDATED WHEN_FAILED RAW_VALUE
9 Power_On_Hours 0x0012 098 098 000 Old_age Always - 16971
12 Power_Cycle_Count 0x0032 100 100 000 Old_age Always - 76
194 Temperature_Celsius 0x0002 125 125 000 Old_age Always - 44 (Lifetime Min/Max 16/53)
199 UDMA_CRC_Error_Count 0x000a 200 200 000 Old_age Always - 0

SMART Error Log Version: 1
No Errors Logged
<snip>

[ringo:root /dev/pts/0]
/tmp# fdisk -l

Disk /dev/hda: 80.0 GB, 80000000000 bytes
255 heads, 63 sectors/track, 9726 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes

Device Boot Start End Blocks Id System
/dev/hda1 * 1 10 80293+ 83 Linux
/dev/hda2 11 201 1534207+ 83 Linux
/dev/hda3 202 226 200812+ 82 Linux swap
/dev/hda4 227 9726 76308750 83 Linux

[ringo:root /dev/pts/0]
/tmp# cat /etc/fstab
# This file is edited by fstab-sync - see 'man fstab-sync' for details
LABEL=/ / ext3 defaults 1 1
LABEL=/boot /boot ext3 defaults 1 2
LABEL=/data /data ext3 defaults 1 2
none /dev/pts devpts gid=5,mode=620 0 0
none /dev/shm tmpfs defaults 0 0
none /proc proc defaults 0 0
none /sys sysfs defaults 0 0
LABEL=SWAP-hda3 swap swap defaults 0 0
<snip>

[ringo:root /dev/pts/0]
tmp# cat /proc/sys/vm/swappiness
60

[ringo:root /dev/pts/0]
tmp# cat /proc/sys/vm/min_free_kbytes
957

[ringo:root /dev/pts/0]
tmp# cat /proc/sys/vm/lowmem_reserve_ratio
cat: /proc/sys/vm/lowmem_reserve_ratio: No such file or directory

[ringo:root /dev/pts/0]
tmp# echo 90 > /proc/sys/vm/swappiness

[ringo:root /dev/pts/0]
tmp# cat /proc/sys/vm/swappiness
90

Re: Disk turns read-only: Workstation 5 crash on RHEL4.1 w/ EXT3 journal er

14. Sep 7, 2005 3:21 PM in response to: JPV
Click to view petr's profile Champion
petr
7,218 posts since
Jul 10, 2003
min_free_kbytes = 957 is definitely too low for 1GB system. You should have something around 2500 (2.5MB) in that file for 1GB system, more if you have slow disks and/or fast processor.
1 2 Previous Next Go to original post

Actions

VMware Developer

SDKs, APIs, Videos, Learn and much more in the Developer community.

Learn More

Developer Sample Code

Increase your developer productivity with VMware API sample code.

Learn More

VMworld Sessions & Labs

Online access to the latest VMworld Sessions & Labs and online services.

Learn more

Purchase PSO Credits Online

Purchase credits to redeem training and consulting services online.

Buy Now

Community Hardware Software

View reported configurations or report your own.

Learn More

VMware vSphere

Come witness the next giant leap in virtualization.

Register Today

Communities