Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

A lot of git-related testcases fail with "Errno::EBUSY: Device or resource busy - ./kernel_builds" #43

Open
simonxuhao opened this issue May 11, 2015 · 2 comments

Comments

@simonxuhao
Copy link

For instance, WriteboostTestsBackingDevice_git_extract_cache_quick.log:

D, [2015-05-11T16:21:38.793363 #14423] DEBUG -- : executing: 'blockdev --getsz /dev/disk/by-id/scsi-35000cca01646b624-part1'
D, [2015-05-11T16:21:38.803996 #14423] DEBUG -- : stdout:
41943040
D, [2015-05-11T16:21:38.804441 #14423] DEBUG -- : executing: 'blockdev --getsz /dev/disk/by-id/scsi-35000cca01646b624-part1'
D, [2015-05-11T16:21:38.808762 #14423] DEBUG -- : stdout:
41943040
D, [2015-05-11T16:21:38.809121 #14423] DEBUG -- : executing: 'blockdev --getsz /dev/disk/by-id/ata-3E128-TS2-550B01_5L003PKF-part1'
D, [2015-05-11T16:21:38.813625 #14423] DEBUG -- : stdout:
20971520
D, [2015-05-11T16:21:38.813974 #14423] DEBUG -- : executing: 'dmsetup create test-dev-246982 --notable'
D, [2015-05-11T16:21:38.820871 #14423] DEBUG -- : writing table: <<table:0 4194304 linear /dev/disk/by-id/scsi-35000cca01646b624-part1 0>>
D, [2015-05-11T16:21:38.821054 #14423] DEBUG -- : executing: 'dmsetup load test-dev-246982 /tmp/dm-table20150511-14423-n4j8n0'
D, [2015-05-11T16:21:38.826766 #14423] DEBUG -- : executing: 'dmsetup resume test-dev-246982'
D, [2015-05-11T16:21:38.913012 #14423] DEBUG -- : executing: 'dmsetup create test-dev-554862 --notable'
D, [2015-05-11T16:21:38.919900 #14423] DEBUG -- : writing table: <<table:0 2097152 linear /dev/disk/by-id/ata-3E128-TS2-550B01_5L003PKF-part1 0>>
D, [2015-05-11T16:21:38.920059 #14423] DEBUG -- : executing: 'dmsetup load test-dev-554862 /tmp/dm-table20150511-14423-elx4qj'
D, [2015-05-11T16:21:38.925612 #14423] DEBUG -- : executing: 'dmsetup resume test-dev-554862'
D, [2015-05-11T16:21:38.968875 #14423] DEBUG -- : executing: 'dmsetup create test-dev-191278 --notable'
D, [2015-05-11T16:21:38.975717 #14423] DEBUG -- : writing table: <<table:0 20480 linear /dev/disk/by-id/ata-3E128-TS2-550B01_5L003PKF-part1 2097152>>
D, [2015-05-11T16:21:38.975876 #14423] DEBUG -- : executing: 'dmsetup load test-dev-191278 /tmp/dm-table20150511-14423-14dz7qi'
D, [2015-05-11T16:21:38.981757 #14423] DEBUG -- : executing: 'dmsetup resume test-dev-191278'
D, [2015-05-11T16:21:39.002556 #14423] DEBUG -- : executing: 'blockdev --getsz /dev/mapper/test-dev-554862'
D, [2015-05-11T16:21:39.006497 #14423] DEBUG -- : stdout:
2097152
D, [2015-05-11T16:21:39.006880 #14423] DEBUG -- : executing: 'dd if=/dev/zero of=/dev/mapper/test-dev-554862 bs=512 count=1 seek=0'
D, [2015-05-11T16:21:39.017327 #14423] DEBUG -- : stderr:
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.000727186 s, 704 kB/s
D, [2015-05-11T16:21:39.017596 #14423] DEBUG -- : executing: 'blockdev --getsz /dev/disk/by-id/scsi-35000cca01646b624-part1'
D, [2015-05-11T16:21:39.021283 #14423] DEBUG -- : stdout:
41943040
D, [2015-05-11T16:21:39.021672 #14423] DEBUG -- : executing: 'dmsetup create test-dev-632684 --notable'
D, [2015-05-11T16:21:39.027566 #14423] DEBUG -- : writing table: <<table:0 4194304 linear /dev/disk/by-id/scsi-35000cca01646b624-part1 0>>
D, [2015-05-11T16:21:39.027717 #14423] DEBUG -- : executing: 'dmsetup load test-dev-632684 /tmp/dm-table20150511-14423-d9h15k'
D, [2015-05-11T16:21:39.034918 #14423] DEBUG -- : executing: 'dmsetup resume test-dev-632684'
D, [2015-05-11T16:21:39.062288 #14423] DEBUG -- : executing: 'mkfs.ext4 -E lazy_itable_init=1 /dev/mapper/test-dev-632684'
D, [2015-05-11T16:21:39.596534 #14423] DEBUG -- : stderr:
mke2fs 1.42.9 (28-Dec-2013)
D, [2015-05-11T16:21:39.597010 #14423] DEBUG -- : stdout:
Filesystem label=
OS type: Linux
Block size=4096 (log=2)
Fragment size=4096 (log=2)
Stride=0 blocks, Stripe width=0 blocks
131072 inodes, 524288 blocks
26214 blocks (5.00%) reserved for the super user
First data block=0
Maximum filesystem blocks=536870912
16 block groups
32768 blocks per group, 32768 fragments per group
8192 inodes per group
Superblock backups stored on blocks:
32768, 98304, 163840, 229376, 294912

Allocating group tables: done
Writing inode tables: done
Creating journal (16384 blocks): done
Writing superblocks and filesystem accounting information: done

D, [2015-05-11T16:21:39.598308 #14423] DEBUG -- : executing: 'mount /dev/mapper/test-dev-632684 ./kernel_builds '
D, [2015-05-11T16:21:39.642655 #14423] DEBUG -- : executing: 'git clone /root/linux-github linux'
D, [2015-05-11T16:22:58.575110 #14423] DEBUG -- : stderr:
Checking out files: 100% (48957/48957), done.
D, [2015-05-11T16:22:58.575519 #14423] DEBUG -- : stdout:
Cloning into 'linux'...
done.
D, [2015-05-11T16:22:58.575969 #14423] DEBUG -- : executing: 'umount ./kernel_builds'
D, [2015-05-11T16:23:02.043542 #14423] DEBUG -- : executing: 'dmsetup remove test-dev-632684'
D, [2015-05-11T16:23:02.064336 #14423] DEBUG -- : executing: 'dmsetup remove test-dev-191278'
D, [2015-05-11T16:23:02.085470 #14423] DEBUG -- : executing: 'dmsetup remove test-dev-554862'
D, [2015-05-11T16:23:02.106307 #14423] DEBUG -- : executing: 'dmsetup remove test-dev-246982'
E, [2015-05-11T16:23:02.123497 #14423] ERROR -- : Error:
test_git_extract_cache_quick(WriteboostTestsBackingDevice):
Errno::EBUSY: Device or resource busy - ./kernel_builds
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/fs.rb:29:in unlink' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/fs.rb:29:indelete'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/fs.rb:29:in umount' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/fs.rb:36:inblock in with_mount'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/prelude.rb:18:in call' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/prelude.rb:18:inbracket_'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/fs.rb:36:in with_mount' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/git.rb:49:ingit_prepare_'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/git.rb:58:in block in git_prepare' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/benchmarking.rb:18:intime_block'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/benchmarking.rb:7:in report_time' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/git.rb:58:ingit_prepare'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/tests.rb:516:in block (2 levels) in test_git_extract_cache_quick' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/ensure_elapsed.rb:13:incall'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/ensure_elapsed.rb:13:in ensure_elapsed_time' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/stack.rb:97:inblock in activate_top_level'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/prelude.rb:6:in bracket' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/device-mapper/lexical_operators.rb:12:inwith_dev'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/stack.rb:95:in activate_top_level' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/tests.rb:515:inblock in test_git_extract_cache_quick'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/ensure_elapsed.rb:13:in call' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/ensure_elapsed.rb:13:inensure_elapsed_time'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/stack.rb:84:in block in activate_support_devs' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/device-mapper/lexical_operators.rb:37:incall'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/device-mapper/lexical_operators.rb:37:in block in with_devs' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/prelude.rb:6:inbracket'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/device-mapper/lexical_operators.rb:32:in with_devs' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/stack.rb:76:inactivate_support_devs'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/tests.rb:508:in `test_git_extract_cache_quick'
I, [2015-05-11T16:23:02.123870 #14423] INFO -- : Peak bufio allocation was 0

@akiradeveloper
Copy link
Contributor

Yes.

Documentation is bit insufficient in dmts.
I think requirement for dm-bufio should be documented.
(You can send PR)

Btw, writeboost's test requires the lastest fio to do stride access.
I asked fio developers to implement it.
see
http://comments.gmane.org/gmane.comp.storage.fio/922

On 2015/05/11 17:48, Simon Xu wrote:

For instance, WriteboostTestsBackingDevice_git_extract_cache_quick.log:

D, [2015-05-11T16:21:38.793363 #14423] DEBUG -- : executing: 'blockdev --getsz /dev/disk/by-id/scsi-35000cca01646b624-part1'
D, [2015-05-11T16:21:38.803996 #14423] DEBUG -- : stdout:
41943040
D, [2015-05-11T16:21:38.804441 #14423] DEBUG -- : executing: 'blockdev --getsz /dev/disk/by-id/scsi-35000cca01646b624-part1'
D, [2015-05-11T16:21:38.808762 #14423] DEBUG -- : stdout:
41943040
D, [2015-05-11T16:21:38.809121 #14423] DEBUG -- : executing: 'blockdev --getsz /dev/disk/by-id/ata-3E128-TS2-550B01_5L003PKF-part1'
D, [2015-05-11T16:21:38.813625 #14423] DEBUG -- : stdout:
20971520
D, [2015-05-11T16:21:38.813974 #14423] DEBUG -- : executing: 'dmsetup create test-dev-246982 --notable'
D, [2015-05-11T16:21:38.820871 #14423] DEBUG -- : writing table: <<table:0 4194304 linear /dev/disk/by-id/scsi-35000cca01646b624-part1 0>>
D, [2015-05-11T16:21:38.821054 #14423] DEBUG -- : executing: 'dmsetup load test-dev-246982 /tmp/dm-table20150511-14423-n4j8n0'
D, [2015-05-11T16:21:38.826766 #14423] DEBUG -- : executing: 'dmsetup resume test-dev-246982'
D, [2015-05-11T16:21:38.913012 #14423] DEBUG -- : executing: 'dmsetup create test-dev-554862 --notable'
D, [2015-05-11T16:21:38.919900 #14423] DEBUG -- : writing table: <<table:0 2097152 linear /dev/disk/by-id/ata-3E128-TS2-550B01_5L003PKF-part1 0>>
D, [2015-05-11T16:21:38.920059 #14423] DEBUG -- : executing: 'dmsetup load test-dev-554862 /tmp/dm-table20150511-14423-elx4qj'
D, [2015-05-11T16:21:38.925612 #14423] DEBUG -- : executing: 'dmsetup resume test-dev-554862'
D, [2015-05-11T16:21:38.968875 #14423] DEBUG -- : executing: 'dmsetup create test-dev-191278 --notable'
D, [2015-05-11T16:21:38.975717 #14423] DEBUG -- : writing table: <<table:0 20480 linear /dev/disk/by-id/ata-3E128-TS2-550B01_5L003PKF-part1 2097152>>
D, [2015-05-11T16:21:38.975876 #14423] DEBUG -- : executing: 'dmsetup load test-dev-191278 /tmp/dm-table20150511-14423-14dz7qi'
D, [2015-05-11T16:21:38.981757 #14423] DEBUG -- : executing: 'dmsetup resume test-dev-191278'
D, [2015-05-11T16:21:39.002556 #14423] DEBUG -- : executing: 'blockdev --getsz /dev/mapper/test-dev-554862'
D, [2015-05-11T16:21:39.006497 #14423] DEBUG -- : stdout:
2097152
D, [2015-05-11T16:21:39.006880 #14423] DEBUG -- : executing: 'dd if=/dev/zero of=/dev/mapper/test-dev-554862 bs=512 count=1 seek=0'
D, [2015-05-11T16:21:39.017327 #14423] DEBUG -- : stderr:
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.000727186 s, 704 kB/s
D, [2015-05-11T16:21:39.017596 #14423] DEBUG -- : executing: 'blockdev --getsz /dev/disk/by-id/scsi-35000cca01646b624-part1'
D, [2015-05-11T16:21:39.021283 #14423] DEBUG -- : stdout:
41943040
D, [2015-05-11T16:21:39.021672 #14423] DEBUG -- : executing: 'dmsetup create test-dev-632684 --notable'
D, [2015-05-11T16:21:39.027566 #14423] DEBUG -- : writing table: <<table:0 4194304 linear /dev/disk/by-id/scsi-35000cca01646b624-part1 0>>
D, [2015-05-11T16:21:39.027717 #14423] DEBUG -- : executing: 'dmsetup load test-dev-632684 /tmp/dm-table20150511-14423-d9h15k'
D, [2015-05-11T16:21:39.034918 #14423] DEBUG -- : executing: 'dmsetup resume test-dev-632684'
D, [2015-05-11T16:21:39.062288 #14423] DEBUG -- : executing: 'mkfs.ext4 -E lazy_itable_init=1 /dev/mapper/test-dev-632684'
D, [2015-05-11T16:21:39.596534 #14423] DEBUG -- : stderr:
mke2fs 1.42.9 (28-Dec-2013)
D, [2015-05-11T16:21:39.597010 #14423] DEBUG -- : stdout:
Filesystem label=
OS type: Linux
Block size=4096 (log=2)
Fragment size=4096 (log=2)
Stride=0 blocks, Stripe width=0 blocks
131072 inodes, 524288 blocks
26214 blocks (5.00%) reserved for the super user
First data block=0
Maximum filesystem blocks=536870912
16 block groups
32768 blocks per group, 32768 fragments per group
8192 inodes per group
Superblock backups stored on blocks:
32768, 98304, 163840, 229376, 294912

Allocating group tables: done
Writing inode tables: done
Creating journal (16384 blocks): done
Writing superblocks and filesystem accounting information: done

D, [2015-05-11T16:21:39.598308 #14423] DEBUG -- : executing: 'mount /dev/mapper/test-dev-632684 ./kernel_builds '
D, [2015-05-11T16:21:39.642655 #14423] DEBUG -- : executing: 'git clone /root/linux-github linux'
D, [2015-05-11T16:22:58.575110 #14423] DEBUG -- : stderr:
Checking out files: 100% (48957/48957), done.
D, [2015-05-11T16:22:58.575519 #14423] DEBUG -- : stdout:
Cloning into 'linux'...
done.
D, [2015-05-11T16:22:58.575969 #14423] DEBUG -- : executing: 'umount ./kernel_builds'
D, [2015-05-11T16:23:02.043542 #14423] DEBUG -- : executing: 'dmsetup remove test-dev-632684'
D, [2015-05-11T16:23:02.064336 #14423] DEBUG -- : executing: 'dmsetup remove test-dev-191278'
D, [2015-05-11T16:23:02.085470 #14423] DEBUG -- : executing: 'dmsetup remove test-dev-554862'
D, [2015-05-11T16:23:02.106307 #14423] DEBUG -- : executing: 'dmsetup remove test-dev-246982'
E, [2015-05-11T16:23:02.123497 #14423] ERROR -- : Error:
test_git_extract_cache_quick(WriteboostTestsBackingDevice):
Errno::EBUSY: Device or resource busy - ./kernel_builds
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/fs.rb:29:in unlink' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/fs.rb:29:indelete'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/fs.rb:29:in umount' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/fs.rb:36:inblock in with_mount'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/prelude.rb:18:in call' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/prelude.rb:18:inbracket_'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/fs.rb:36:in with_mount' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/git.rb:49:ingit_prepare_'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/git.rb:58:in block in git_prepare' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/benchmarking.rb:18:intime_block'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/benchmarking.rb:7:in report_time' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/git.rb:58:ingit_prepare'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/tests.rb:516:in block (2 levels) in test_git_extract_cache_quick' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/ensure_elapsed.rb:13:incall'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/ensure_elapsed.rb:13:in ensure_elapsed_time' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/stack.rb:97:inblock in activate_top_level'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/prelude.rb:6:in bracket' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/device-mapper/lexical_operators.rb:12:inwith_dev'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/stack.rb:95:in activate_top_level' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/tests.rb:515:inblock in test_git_extract_cache_quick'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/ensure_elapsed.rb:13:in call' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/ensure_elapsed.rb:13:inensure_elapsed_time'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/stack.rb:84:in block in activate_support_devs' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/device-mapper/lexical_operators.rb:37:incall'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/device-mapper/lexical_operators.rb:37:in block in with_devs' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/prelude.rb:6:inbracket'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/device-mapper/lexical_operators.rb:32:in with_devs' /root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/stack.rb:76:inactivate_support_devs'
/root/device_mapper_test/device-mapper-test-suite/lib/dmtest/tests/writeboost/tests.rb:508:in `test_git_extract_cache_quick'
I, [2015-05-11T16:23:02.123870 #14423] INFO -- : Peak bufio allocation was 0


Reply to this email directly or view it on GitHub:
#43

@simonxuhao
Copy link
Author

This issue is seen in all /git_extract/ testcases, e.g. BurstyWriteTests_git_extract_cache_16.log:

...
D, [2015-05-12T10:25:26.357562 #7048] DEBUG -- : stdout:
Cloning into 'linux'...
done.
D, [2015-05-12T10:25:26.358230 #7048] DEBUG -- : executing: 'umount ./kernel_bui
lds'
D, [2015-05-12T10:25:29.623351 #7048] DEBUG -- : executing: 'dmsetup remove test
-dev-157551'
D, [2015-05-12T10:25:29.704410 #7048] DEBUG -- : executing: 'cache_check /dev/mapper/test-dev-464213'
D, [2015-05-12T10:25:29.721925 #7048] DEBUG -- : stderr:
examining superblock
examining mapping array
examining hint array
examining discard bitset
D, [2015-05-12T10:25:29.722315 #7048] DEBUG -- : executing: 'dmsetup remove test-dev-676561'
D, [2015-05-12T10:25:29.743350 #7048] DEBUG -- : executing: 'dmsetup remove test-dev-65086'
D, [2015-05-12T10:25:29.758249 #7048] DEBUG -- : executing: 'dmsetup remove test-dev-464213'
E, [2015-05-12T10:25:29.773541 #7048] ERROR -- : Error:
test_git_extract_cache_16(BurstyWriteTests):
Errno::EBUSY: Device or resource busy - ./kernel_builds
...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants