umount problems after changing to Slackware64

rutrow · 12-26-2010, 11:12 AM

We recently switched from slackware-13.0 to slackware64-13.1. While testing out our daily backup scripts found some strange behavior that did not occur on the old OS. We use rsync to mostly mirror sda2 (80 GB SSD) to sdb2 (150 GB spindle drive).

Previous backup sequence:
mount sdb2
rsync sda2 to sdb2
umount sdb2

Now we have to add a sync and sleep step before umount, otherwise the strange behavior occurs. This being that df now reports the wrong disk size for sdb2 and the drive constantly thrashes, never stopping until we reset the machine. Upon reboot, e2fsck doesn't report any errors and the drive size is correct. We have tried a different backup drive with the same results.

My understanding was that sync'ing before umount was not necessary since umount automatically syncs or will report the drive as busy.

Anyone else experience this or know why the behavior has changed?

Bruce Hill · 12-27-2010, 02:38 AM

You should post your scripts, the output of "df -hT" for both mounted
filesystems, "dmesg" output, and the output of "/sbin/fdisk -l" at a bare
minimum. That way someone can look at what you have vs. your synopsis.

rutrow · 12-27-2010, 10:31 AM

Output of 'df -hT' for sda2 and sdb2

Code:

Filesystem    Type    Size  Used Avail Use% Mounted on
/dev/root     ext4     66G  2.0G   61G   4% /
/dev/sdb2     ext4     50G  2.3G   45G   5% /mnt/sdb2

When the problem occurs, size for sdb2 becomes 66G.... same size as sda2.

This is from /var/log/messages, but same was in dmesg:

Code:

Dec 26 09:05:30 val kernel: INFO: task umount:31257 blocked for more than 120 seconds.
Dec 26 09:05:30 val kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 26 09:05:30 val kernel: umount        D 0000000000000000     0 31257      1 0x00000004
Dec 26 09:05:30 val kernel:  ffff88008d40fca8 0000000000000082 0000000000000000 ffff8801080141f8
Dec 26 09:05:30 val kernel:  ffff88008d40fc78 ffffffff810c5f53 ffff8800f3b95f60 ffff880006293b80
Dec 26 09:05:30 val kernel:  ffff88008d40ffd8 000000000000dde8 ffffffff82048020 ffff8800f3b95cc0
Dec 26 09:05:30 val kernel: Call Trace:
Dec 26 09:05:30 val kernel:  [<ffffffff810c5f53>] ? wait_on_page_bit+0x73/0x80
Dec 26 09:05:30 val kernel:  [<ffffffff811217b0>] ? bdi_sched_wait+0x0/0x20
Dec 26 09:05:30 val kernel:  [<ffffffff811217be>] bdi_sched_wait+0xe/0x20
Dec 26 09:05:30 val kernel:  [<ffffffff81a013af>] __wait_on_bit+0x5f/0x90
Dec 26 09:05:30 val kernel:  [<ffffffff8103309e>] ? activate_task+0x2e/0x40
Dec 26 09:05:30 val kernel:  [<ffffffff811217b0>] ? bdi_sched_wait+0x0/0x20
Dec 26 09:05:30 val kernel:  [<ffffffff81a01458>] out_of_line_wait_on_bit+0x78/0x90
Dec 26 09:05:30 val kernel:  [<ffffffff81065da0>] ? wake_bit_function+0x0/0x40
Dec 26 09:05:30 val kernel:  [<ffffffff8103c5e5>] ? wake_up_process+0x15/0x20
Dec 26 09:05:30 val kernel:  [<ffffffff811228cf>] bdi_sync_writeback+0x6f/0x80
Dec 26 09:05:31 val kernel:  [<ffffffff81122902>] sync_inodes_sb+0x22/0xf0
Dec 26 09:05:31 val kernel:  [<ffffffff81126442>] __sync_filesystem+0x82/0x90
Dec 26 09:05:31 val kernel:  [<ffffffff8112663b>] sync_filesystem+0x4b/0x70
Dec 26 09:05:31 val kernel:  [<ffffffff81102577>] generic_shutdown_super+0x27/0x100
Dec 26 09:05:31 val kernel:  [<ffffffff81102681>] kill_block_super+0x31/0x50
Dec 26 09:05:31 val kernel:  [<ffffffff81103789>] deactivate_super+0x69/0x80
Dec 26 09:05:31 val kernel:  [<ffffffff8111ad37>] mntput_no_expire+0xa7/0xf0
Dec 26 09:05:31 val kernel:  [<ffffffff8111b113>] sys_umount+0x63/0x390
Dec 26 09:05:31 val kernel:  [<ffffffff81026ab7>] ? do_page_fault+0x137/0x2d0
Dec 26 09:05:31 val kernel:  [<ffffffff810028db>] system_call_fastpath+0x16/0x1b

Output of 'fdisk -l':

Code:

Disk /dev/sda: 80.0 GB, 80025280000 bytes
255 heads, 63 sectors/track, 9729 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disk identifier: 0xdf0a425f

   Device Boot      Start         End      Blocks   Id  System
/dev/sda1               1        1045     8393931   82  Linux swap
/dev/sda2            1046        9729    69754230   83  Linux

Disk /dev/sdb: 150.0 GB, 150039945216 bytes
255 heads, 63 sectors/track, 18241 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disk identifier: 0xadfbc15a

   Device Boot      Start         End      Blocks   Id  System
/dev/sdb1               1        1045     8393931   82  Linux swap
/dev/sdb2            1046        7573    52436160   83  Linux
/dev/sdb3            7574       14101    52436160   83  Linux
/dev/sdb4           14102       18241    33254550   83  Linux

The backup script:

Code:

#!/bin/bash

LOGFILE=/tmp/${0##*/}.log

umask 077

exec &> $LOGFILE

cd /

echo -e "START: `date`\n"

umount /mnt/sdb2

e2fsck -p /dev/sdb2

echo

if ! mount /mnt/sdb2; then
  echo -e "Unable to mount /mnt/sdb2.\nSTOP: `date`"
  mail -s "Error Mounting Backup Drive" root < $LOGFILE
  exit 1
fi

nice rsync -aRv --exclude-from=/root/bin/backup/exclude.txt --delete --delete-excluded \
  bin \
  boot \
  etc \
  home \
  lib \
  lib64 \
  root \
  sbin \
  usr \
  var \
  /mnt/sdb2/

echo

df

# Uncomment to fix the problem
# sync
# sleep 10

umount /mnt/sdb2

echo -e "\nSTOP: `date`"

mail -s "VAL Backup to sdb2 Log" root < $LOGFILE

rm -f $LOGFILE