pvmove hangs

Hi!

On my computer, pvmove just hangs at 0.2% done. First it looked like the reason was that I hadn't loaded dm-mirror before calling pvmove. Modprobe was called automatically, but tried to write to /var/log/ksymoops/, which was on one of the lvs to move.

But then I booted to singe user mode and didn't mount any partitions on lvm, and still, pvmove was hanging at 0.2%.

Another unusual detail about my installation is that the target pv is on a degraded raid1 array. Perhaps there is some locking issue?

Jan

I just noticed I forgot an important detail: Version numbers :-)

# pvmove --version
  LVM version:     2.00.05 (2003-07-18)
  Library version: 1.00.02-ioctl (2003-07-12)
  Driver version:  4.0.1

Jan

If pvmove fails, you can use 'pvmove --abort' to abandon it or 'pvmove' on its own [or with same source pv as before] to retry. xxchange -ay may also attempt to restart pvmoves in progress (leaving a pvmove daemon running).

Need more precise description of what you mean by 'hanging'.

And the usual diagnostics: debug log file from the command that should have set the pvmove running, any kernel error messages, lvm.conf, a copy of the current VG's metadata [e.g. with vgcfgbackup -f] etc. If pvmove process itself freezes, then a long/wide 'ps' output for that process, kcopyd & kmirrord (incl cols: NI, VSZ, RSS, STAT and symbolic WCHAN).

Alasdair

[email protected]

Good news (perhaps?):
If I move only single LVs (ie., I specify one LV with -n on pvmove), it seems to work.
Perhaps the problem is that source and target PV have exactly the same number of extents? Of-by-one error, if the target volume gets completely filled up by the pvmove?

Jan

Who knows?

The log file might show whether that theory is correct or not.

If you want me to look at this, you need to supply some of the information requested in my last email: your description of the problem so far is too vague.

Alasdair

[email protected]

I sent it to the list a few hours ago, but it seems like it didn't go through. Perhaps it exceeded some size limitation?

However, now I put the files on http://gondor.com/lvm/
They do contain the following:

lvm2.log debug log of pvmove, vgcfgbackup (to save the new

		config) and pvmove --abort

lvm.conf obvious
config-old config before pvmove
config-new config after pvmove
ps output of ps while (first) pvmove is running

I checked the off-by-one theory, by filling up most of the target PV with a dummy partition and moving a single LV which exactly fits in to the remaining extents. The pvmove succeeded, so this probably wasn't the cause.

Jan

Quite likely - after the 1.9MB message slipped through the net last week.

Alasdair

[email protected]

This is the first clue:
activate/dev_manager.c:487 pvmove Mirror status: 2 003:004 009:002 383/384 activate/dev_manager.c:532 pvmove Mirror percent: 99.739586

383/384 means the kernel mirror has only successfully copied 383 out of 384 512-KB regions from (major, minor) (3,4) to (9,2).

The first pvmove segment has
12 16MB extents = 393216 sectors = 384 512KB regions.

Can you check (e.g. using dd) all the old sectors can be read OK, and the new ones written to OK? (Though you're not seeing kernel error messages; but some volume moves work OK, so an off-by-one theory is unlikely or nothing would work?)

The first entry of 'dmsetup table vgraid-pvmove0' would show you the sector ranges - 30448+3156 on pv1=/dev/hda4, length above & 384 on pv0=/dev/md2 ?

[NB Be careful not to overwrite data - if you've done some other successful pvmoves since, some of those /dev/md2 sectors might now be allocated onto.]

We haven't implemented bad sector error reporting and handling yet, so for now, you have to construct pvmoves to avoid any bad sectors.

Alasdair

Well, now after I did some pvmoves of individual LVs, pvmove /dev/hda4 hangs at a different point:

activate/dev_manager.c:487 pvmove Mirror status: 2 003:004 009:002 511/512 activate/dev_manager.c:532 pvmove Mirror percent: 99.804688

dmsetup says:

0 524288 mirror core 1 1024 2 003:004 111146736 009:002 56852864 524288 229376 linear 003:004 88864496
753664 2326528 linear 003:004 89093872
[...]

I hope I understand these numbers correctly: The first line means that the virtual device vgraid-pvmove0 starts with 524288 blocks (512 byte each). These are located at position 111146736 on /dev/hda4 and 56852864 on /dev/md2. (But I don't know what core 1 1024 2 means)

I can read/write these areas with dd, without error messages.

I don't think the drives have bad sectors - at least I didn't see any signs of bad sectors by now.

And I pvmoved a 19GB LV, much more than the global pvmove gets done. All the moves had decent performance, ~20MB/s, where the source drive only reads ~30MB/s with dd. The only strange thing I saw was that there sometimes where some seconds without any disk activity at all.

Jan

That'll be because of the pvmove polling mode - by default it only checks (and displays) each segment's pvmove progress
every 15 seconds. For 5 sec. intervals use pvmove -i5
or for best performance (but no progress displays *during* segments) try -i0.

Alasdair

core means the data recording the state of the mirror is held in-core - i.e. it is not a persistent mirror [No other options apart from 'core' available yet]

1 means 1 parameter associated with 'core' follows:
1024 is the number of sectors moved at once (ie 512KB)

2 means 2 mirror devices follow

Alasdair

[email protected]

Puzzling. But we can think of some explanations that could tie this in with the 383/384 problem.

I'd like to see the debug log file/strace for that pvmove --abort and the full ps output for the process (incl decoded wchan and process state, nice value, resident memory size & whether its CPU time is static or increasing) - before and after issuing the 'kill -9' that doesn't work.

We're probably going to need to start sending you patches to instrument the kernel if we are to work out what's going on here [unless you happen to have the machine set up for kgdb].

Also, careful use of 'dmsetup' should let us deduce some internal state.

Do you use irc or IM - might speed things up if so?

Alasdair

I don't use kgdb, but I'd happily apply patches if this may help finding the problem.

jannic on the freenode IRC network, or [email protected] on jabber. I'd prefer jabber, because on IRC I often miss messages :-)

But I don't think I'll have time this evening - perhaps later, but I'm not sure. Tomorrow evening I'll probably have enough time to do some more testing.
How are you reachable by IRC or IM?

Jan

The ps simply says

F UID PID PPID PRI NI VSZ RSS WCHAN STAT TTY TIME COMMAND

4 0 24006 1180 1 -18 14140 14140 down D<L tty1 0:00 pvmove --abort

(or numeric:)
4 0 24006 1180 1 -18 14140 14140 105b14 D<L tty1 0:00 pvmove --abort

This doesn't change with kill -9, all stays exactly the same. I do not yet have a logfile of pvmove --abort.

But http://gondor.com/lvm/lvm2.log.20030818 does contain the complete logfile of pvmove -v /dev/hda4.

I'm going to sleep now. Lets do further debugging tomorrow (Tuesday), if that's ok for you.

Jan

Hi!

Unfortunately I had some network problems today, so the debugging session was shorter than expected.

But I did gather another logfile with activation=1.
It's available from http://gondor.com/lvm/lvm2.log.20030819
Additionally, there is a file 'typescript' in the same directory, which contains output from dmsetup ls and dmsetup -v table vgraid-pvmove0.

Jan

I noticed the WCHAN fields in my ps output were not very useful, because they pointed to a module and were not decoded.

So I took the numeric value (92fa83) and looked it up by hand. It seems to point to the schedule() call in line 56 of dm-daemon.c for both kcopyd and kmirrord.

And then, I made a quite worrying observation: When the hanging happens, the device being copied is in a completely garbled state. In this case, /dev/vgraid/lvol5 didn't look like an ext3 filesystem at all.

So I looked at the underlying devices, and both /dev/hda4 and /dev/md2 had a copy of the actual filesystem, only differing in the last 512K. This conforms to the fact that the mirroring was done for all but one 512K block. But these 512K are completely different (target device all zeroes).

However, these are only the underlying devices. Looking at /dev/vgraid/lvol5 a little bit closer revealed that it contained parts of some other filesystem. Very strange. And worrying. I don't even want to know if writing to this LV would overwrite some unrelated partition.

Jan

Please confirm which kernel you are using, and the device-mapper patch(es) you applied. [patches/linux-2.4.2?* from the 1.00.02 device-mapper tarball?]

Some more diagnostics:
check that you have 'activation = 1' and 'level = 7' in the log{} section of lvm.conf and if not, recreate a problem pvmove application log (The you put on the web seems incomplete)
['activation = 1' setting is only meant for use when diagnosing problems like this - don't leave it there permanently]

Use dmsetup to see what's going on:
run 'dmsetup ls' to get a list of internal device names, then 'dmsetup -v table <device_name_shown_in_ls>'
on all the relevant ones (e.g. vgraid-lvol5*)

After all the interruptions you've had, check the /dev/vgraid/lvol5 symlink (->/dev/mapper/vgraid-lvol5) & destination major/minor is still right.

Check the current metadata (with vgcfgbackup) still looks right. [Does it show pvmove(s) in progress, or is it clean again?]

Alasdair

[email protected]

It's 2.4.21, and yes, both linux-2.4.21-devmapper-ioctl.patch and linux-2.4.21-VFS-lock.patch from the 1.00.02 tarball are applied.

I have level = 7, but not activation = 1. I'll try it again later, when I'm back at the console... don't want to hang the computer via ssh :-)

I had a look at these and didn't see anything unusual, but I'll check again carefully.

lvol5 was mounted when the problems started (errors on ls on that partition), so it's surely not a symlink problem, as the kernel doesn't access a mounted device via the symlink.

When pvmove hangs, vgcfgbackup shows the pvmove in progress, even after CTRL-C (which is expected), and pvmove --abort doesn't work at all, as I said.
So I always had to restore LVM2 to a sane state with vgcfgrestore. After that, I reboot and get LVM back up running cleanly. Even lvol5 was not damaged, because the garbage on the logical volume never got written to the underlying device, and vgcfgrestore removed all traces of the incomplete pvmove.

Jan

Does your System.map file correspond to the running kernel? [See ps man page / strace to check where it's getting that file from]

Alasdair

[email protected]

Sure it is :-)
(I use debian make-kpkg to build a kernel .deb, which makes sure that the right System.map file gets installed together with the kernel)

But it doesn't contain symbols which get defined by modules. And even /proc/ksymoops only contains exported symbols, which daemon() from dm-daemon.c is not. So I looked at the next exported symbol (dm_daemon_start), took the difference between these two addresses, and went back the number of bytes in objdump --disassemble, and compared that to the sourcecode to find the actual positions.

Even though I don't know x86 assembly too well, it was not difficult to match assembly instructions to C source code, as the source at this position is quite low-level.

Jan