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

Add .travis.yml #6829

Merged
merged 1 commit into from
Nov 13, 2017
Merged

Add .travis.yml #6829

merged 1 commit into from
Nov 13, 2017

Conversation

gmelikov
Copy link
Member

@gmelikov gmelikov commented Nov 6, 2017

Description

Travis builders have maximum work time ~49 minutes,
so we have to use 5 builders.

Example: https://travis-ci.org/gmelikov/zfs/builds/297947563

In future we can add:

  • SPL commit id from commit message
  • test tags specified in commit message

Signed-off-by: George Melikov [email protected]

Motivation and Context

Now we can use Travis-ci service on every branch and fork. For example, if you setup Travis on your fork, then you can test every commit without PR to main repository or manual install VM for zfs-tests.

How Has This Been Tested?

Example: https://travis-ci.org/gmelikov/zfs/builds/297947563

Types of changes

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Performance enhancement (non-breaking change which improves efficiency)
  • Code cleanup (non-breaking change which makes code smaller or more readable)
  • Breaking change (fix or feature that would cause existing functionality to change)
  • Documentation (a change to man pages or other documentation)

Checklist:

  • My code follows the ZFS on Linux code style requirements.
  • I have updated the documentation accordingly.
  • I have read the CONTRIBUTING document.
  • I have added tests to cover my changes.
  • All new and existing tests passed.
  • All commit messages are properly formatted and contain Signed-off-by.
  • Change has been approved by a ZFS on Linux member.

@@ -57,6 +57,10 @@
# before data integrity is compromised
#

if [[ $TRAVIS = 'true' ]]; then
log_unsupported "Test case is disabled in Travis-ci (timeout kill)"
fi
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We're seeing spurious failures for the same test case in buildbot too. Why don't we simply disable it across the board for now and open an issue in the tracker so we can track it and get it properly resolved.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agree, #6840

.travis.yml Outdated
- sudo apt-get install --yes -qq build-essential autoconf libtool gawk alien fakeroot linux-headers-$(uname -r)
- sudo apt-get install --yes -qq zlib1g-dev uuid-dev libattr1-dev libblkid-dev libselinux-dev libudev-dev libssl-dev
# packages for tests
- sudo apt-get install --yes -qq libdevmapper-dev parted lsscsi ksh attr acl nfs-kernel-server fio
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can remove libdevmapper-dev this dependency was only added briefly. I'll make sure it get's dropped from the wiki documentation.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You don't forcibly need to issue arbitrary APT commands, Travis has a module so you can list what packages you need and it will install automatically: https://docs.travis-ci.com/user/installing-dependencies/#Installing-Packages-with-the-APT-Addon

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@behlendorf thanks, removed it.

@sylveon thanks, unfortunately it doesn't give any gain, only more verbose, which we don't need. I'll revert it.

sudo: required
env:
global:
# Travis limits maximum log size, we have to cut tests output
Copy link
Contributor

@behlendorf behlendorf Nov 6, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we're forced to truncate the logs it would be good to make the build itself quieter so there are more lines available for the test results.

This could be accomplished by running the testing in tree by using make --no-print-directory -s and it would have the upside of speeding up the build which will allow more time for testing.

@codecov
Copy link

codecov bot commented Nov 7, 2017

Codecov Report

Merging #6829 into master will increase coverage by 0.02%.
The diff coverage is n/a.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #6829      +/-   ##
==========================================
+ Coverage   75.12%   75.14%   +0.02%     
==========================================
  Files         297      297              
  Lines       94468    94444      -24     
==========================================
+ Hits        70970    70973       +3     
+ Misses      23498    23471      -27
Flag Coverage Δ
#kernel 74.15% <ø> (-0.33%) ⬇️
#user 67.4% <ø> (+0.23%) ⬆️
Impacted Files Coverage Δ
module/icp/algs/skein/skein_port.h 0% <0%> (-100%) ⬇️
module/zfs/dmu_tx.c 81.67% <0%> (-4.19%) ⬇️
cmd/zed/agents/zfs_retire.c 77.01% <0%> (-2.49%) ⬇️
module/zfs/zrlock.c 82.81% <0%> (-1.57%) ⬇️
module/zfs/dsl_userhold.c 88.49% <0%> (-1.2%) ⬇️
cmd/zed/agents/zfs_diagnosis.c 73.02% <0%> (-1.18%) ⬇️
module/zfs/bptree.c 92.63% <0%> (-1.06%) ⬇️
module/zfs/dsl_pool.c 93.3% <0%> (-0.75%) ⬇️
module/zfs/zio_checksum.c 98.31% <0%> (-0.57%) ⬇️
lib/libzpool/kernel.c 69.51% <0%> (-0.49%) ⬇️
... and 38 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 5277f20...2e94ce3. Read the comment docs.

- sh autogen.sh
- ./configure
- make --no-print-directory -s pkg-utils pkg-kmod
- sudo dpkg -i *.deb
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we skip building packages entire that should speed up the build. What do you think about this?

    - git clone --depth=1 https://github.com/zfsonlinux/spl
    - cd spl
    - sh autogen.sh
    - ./configure
    - make --no-print-directory -s
    - cd ..
    - sh autogen.sh
    - ./configure --with-spl=$(pwd)/spl
    - make --no-print-directory -s

Then assuming we're still in the root of the zfs git tree.

   - sudo ./scripts/zfs.sh
   - sudo ./scripts/zfs-helpers.sh -iv
   - travis_wait 50 ./scripts/zfs-tests.sh -v -T $ZFS_TEST_TAGS

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, but unfortunately, while compilation time decreased, tests time was longer (I wonder why), and there is a problem with zfs_destroy_001_pos test in such case. Reverted.

@gmelikov gmelikov force-pushed the travis3 branch 4 times, most recently from fe07f15 to c05faed Compare November 8, 2017 13:07
Copy link
Contributor

@behlendorf behlendorf left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The approach looks fine to me, but in the latest run I saw you're still hitting timeouts. Just let me know when you have things tuned to your liking.

@@ -0,0 +1,38 @@
language: c
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does this file need to be in the root of the tree or can it be moved to the .github directory?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unfortunately it has to be in root travis-ci/travis-ci#5519

@gmelikov gmelikov force-pushed the travis3 branch 5 times, most recently from 3b771e4 to 1aab996 Compare November 9, 2017 11:15
@gmelikov
Copy link
Member Author

I've fitted it in 5 builders, so now we can get all results in 50 minutes.

Last build https://travis-ci.org/gmelikov/zfs/builds/299583733

Last problem is with zfs_destroy_001_pos - it consistently fails:

Test: /home/travis/build/gmelikov/zfs/tests/zfs-tests/tests/functional/cli_root/zfs_destroy/zfs_destroy_001_pos (run as root) [00:03] [FAIL]
06:50:03.11 ASSERTION: 'zfs destroy -r|-R|-f|-rf|-Rf <fs|ctr|vol|snap>' should  recursively destroy all children.
06:50:03.11 NOTE: Starting test: zfs destroy -r testpool/testctr
06:50:03.22 SUCCESS: zfs create testpool/testctr
06:50:03.31 SUCCESS: zfs create testpool/testctr/testfs
06:50:03.37 SUCCESS: zfs create -V 150m testpool/testctr/testvol
06:50:06.46 newfs /dev/zvol/testpool/testctr/testvol > /dev/null
06:50:06.46 NOTE: Performing test-fail callback (/home/travis/build/gmelikov/zfs/tests/zfs-tests/callbacks/zfs_dbgmsg.ksh)
06:50:06.46 =================================================================
06:50:06.46  Tailing last 200 lines of zfs_dbgmsg log
06:50:06.46 =================================================================
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj34
06:50:06.46 1510210203   txg.c:657:txg_wait_synced(): txg=3 quiesce_txg=10 sync_txg=9
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj70
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   txg.c:657:txg_wait_synced(): txg=10 quiesce_txg=10 sync_txg=10
06:50:06.46 1510210203   txg.c:661:txg_wait_synced(): broadcasting sync more tx_synced=9 waiting=10 dp=ffff8800b93a1000
06:50:06.46 1510210203   txg.c:594:txg_quiesce_thread(): txg=10 quiesce_txg=11 sync_txg=10
06:50:06.46 1510210203   txg.c:602:txg_quiesce_thread(): quiesce done, handing off txg 10
06:50:06.46 1510210203   txg.c:543:txg_sync_thread(): txg=10 quiesce_txg=11 sync_txg=10
06:50:06.46 1510210203   dnode_sync.c:120:free_blocks(): ds=ffff8800b934d000 obj=2 num=1
06:50:06.46 1510210203   spa_history.c:309:spa_history_log_sync(): command: lt-zfs set mountpoint=/var/tmp/testdir testpool/testfs
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=131 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=132 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=133 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=134 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=135 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=136 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e000 obj=0 txg=10 blocksize=16384 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e000 obj=1 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e000 obj=32 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e000 obj=33 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e000 obj=34 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e000 obj=35 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e000 obj=36 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   zap_micro.c:627:mzap_upgrade(): upgrading obj=36 with 7 chunks
06:50:06.46 1510210203   spa_history.c:317:spa_history_log_sync(): txg 10 create testpool/testctr (id 134) 
06:50:06.46 1510210203   dnode_sync.c:62:dnode_increase_indirection(): os=ffff8800b934e000 obj=0, increase to 6
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e000 obj=18446744073709551615 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e000 obj=18446744073709551614 txg=10 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode_sync.c:120:free_blocks(): ds=          (null) obj=3e num=1
06:50:06.46 1510210203   txg.c:510:txg_sync_thread(): waiting; tx_synced=10 waiting=10 dp=ffff8800b93a1000
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj133
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934b800 obj=3 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   txg.c:657:txg_wait_synced(): txg=3 quiesce_txg=11 sync_txg=10
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   txg.c:657:txg_wait_synced(): txg=11 quiesce_txg=11 sync_txg=11
06:50:06.46 1510210203   txg.c:661:txg_wait_synced(): broadcasting sync more tx_synced=10 waiting=11 dp=ffff8800b93a1000
06:50:06.46 1510210203   txg.c:594:txg_quiesce_thread(): txg=11 quiesce_txg=12 sync_txg=11
06:50:06.46 1510210203   txg.c:602:txg_quiesce_thread(): quiesce done, handing off txg 11
06:50:06.46 1510210203   txg.c:543:txg_sync_thread(): txg=11 quiesce_txg=12 sync_txg=11
06:50:06.46 1510210203   spa_history.c:342:spa_history_log_sync(): ioctl create
06:50:06.46 1510210203   spa_history.c:309:spa_history_log_sync(): command: lt-zfs create testpool/testctr
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=137 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=138 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=139 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=140 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=141 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e800 obj=0 txg=11 blocksize=16384 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e800 obj=1 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e800 obj=32 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e800 obj=33 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e800 obj=34 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e800 obj=35 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e800 obj=36 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   zap_micro.c:1308:zap_update(): upgrading obj 36: intsz=2 numint=14 name=2
06:50:06.46 1510210203   zap_micro.c:627:mzap_upgrade(): upgrading obj=36 with 7 chunks
06:50:06.46 1510210203   spa_history.c:317:spa_history_log_sync(): txg 11 create testpool/testctr/testfs (id 140) 
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dnode_sync.c:62:dnode_increase_indirection(): os=ffff8800b934e800 obj=0, increase to 6
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e800 obj=18446744073709551615 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934e800 obj=18446744073709551614 txg=11 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode_sync.c:120:free_blocks(): ds=          (null) obj=3e num=1
06:50:06.46 1510210203   txg.c:510:txg_sync_thread(): waiting; tx_synced=11 waiting=11 dp=ffff8800b93a1000
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj139
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b934d800 obj=2 txg=12 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj139
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testfs in obj133
06:50:06.46 1510210203   txg.c:657:txg_wait_synced(): txg=3 quiesce_txg=12 sync_txg=11
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   txg.c:657:txg_wait_synced(): txg=12 quiesce_txg=12 sync_txg=12
06:50:06.46 1510210203   txg.c:661:txg_wait_synced(): broadcasting sync more tx_synced=11 waiting=12 dp=ffff8800b93a1000
06:50:06.46 1510210203   txg.c:594:txg_quiesce_thread(): txg=12 quiesce_txg=13 sync_txg=12
06:50:06.46 1510210203   txg.c:602:txg_quiesce_thread(): quiesce done, handing off txg 12
06:50:06.46 1510210203   txg.c:543:txg_sync_thread(): txg=12 quiesce_txg=13 sync_txg=12
06:50:06.46 1510210203   spa_history.c:342:spa_history_log_sync(): ioctl create
06:50:06.46 1510210203   spa_history.c:309:spa_history_log_sync(): command: lt-zfs create testpool/testctr/testfs
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=143 txg=12 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=144 txg=12 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=145 txg=12 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=146 txg=12 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=147 txg=12 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8800b93a0000 obj=148 txg=12 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8802153fc000 obj=0 txg=12 blocksize=16384 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8802153fc000 obj=1 txg=12 blocksize=8192 ibs=17 dn_slots=1
06:50:06.46 1510210203   dnode.c:576:dnode_allocate(): os=ffff8802153fc000 obj=2 txg=12 blocksize=512 ibs=17 dn_slots=1
06:50:06.46 1510210203   spa_history.c:317:spa_history_log_sync(): txg 12 create testpool/testctr/testvol (id 146) 
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dnode_sync.c:62:dnode_increase_indirection(): os=ffff8802153fc000 obj=0, increase to 6
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   txg.c:657:txg_wait_synced(): txg=3 quiesce_txg=13 sync_txg=12
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dnode_sync.c:120:free_blocks(): ds=          (null) obj=3e num=1
06:50:06.46 1510210203   txg.c:510:txg_sync_thread(): waiting; tx_synced=12 waiting=12 dp=ffff8800b93a1000
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   txg.c:657:txg_wait_synced(): txg=13 quiesce_txg=13 sync_txg=13
06:50:06.46 1510210203   txg.c:661:txg_wait_synced(): broadcasting sync more tx_synced=12 waiting=13 dp=ffff8800b93a1000
06:50:06.46 1510210203   txg.c:594:txg_quiesce_thread(): txg=13 quiesce_txg=14 sync_txg=13
06:50:06.46 1510210203   txg.c:602:txg_quiesce_thread(): quiesce done, handing off txg 13
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   spa_history.c:317:spa_history_log_sync(): txg 13 set testpool/testctr/testvol (id 146) refreservation=164364288
06:50:06.46 1510210203   dnode_sync.c:120:free_blocks(): ds=          (null) obj=3e num=1
06:50:06.46 1510210203   txg.c:510:txg_sync_thread(): waiting; tx_synced=13 waiting=13 dp=ffff8800b93a1000
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up %recv in obj145
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testctr in obj34
06:50:06.46 1510210203   dsl_dir.c:455:dsl_dir_hold(): looking up testvol in obj133
06:50:06.47 =================================================================
06:50:06.47  End of zfs_dbgmsg log
06:50:06.47 =================================================================
06:50:06.47 NOTE: Performing test-fail callback (/home/travis/build/gmelikov/zfs/tests/zfs-tests/callbacks/zfs_dmesg.ksh)
06:50:06.47 =================================================================
06:50:06.47  Tailing last 200 lines of dmesg log
06:50:06.47 =================================================================
06:50:06.47 [    0.560501] NetLabel:  protocols = UNLABELED CIPSOv4
06:50:06.47 [    0.561243] NetLabel:  unlabeled traffic allowed by default
06:50:06.47 [    0.562143] amd_nb: Cannot enumerate AMD northbridges
06:50:06.47 [    0.562905] clocksource: Switched to clocksource kvm-clock
06:50:06.47 [    0.571340] pnp: PnP ACPI init
06:50:06.47 [    0.571908] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active)
06:50:06.47 [    0.572585] pnp 00:01: Plug and Play ACPI device, IDs PNP0303 (active)
06:50:06.47 [    0.572629] pnp 00:02: Plug and Play ACPI device, IDs PNP0f13 (active)
06:50:06.47 [    0.572676] pnp 00:03: Plug and Play ACPI device, IDs PNP0501 (active)
06:50:06.47 [    0.572713] pnp 00:04: Plug and Play ACPI device, IDs PNP0501 (active)
06:50:06.47 [    0.572752] pnp 00:05: Plug and Play ACPI device, IDs PNP0501 (active)
06:50:06.47 [    0.572789] pnp 00:06: Plug and Play ACPI device, IDs PNP0501 (active)
06:50:06.47 [    0.572930] pnp: PnP ACPI: found 7 devices
06:50:06.47 [    0.580296] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
06:50:06.47 [    0.581681] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
06:50:06.47 [    0.581683] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]
06:50:06.47 [    0.581685] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
06:50:06.47 [    0.581686] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window]
06:50:06.47 [    0.581720] NET: Registered protocol family 2
06:50:06.47 [    0.582469] TCP established hash table entries: 65536 (order: 7, 524288 bytes)
06:50:06.47 [    0.583662] TCP bind hash table entries: 65536 (order: 8, 1048576 bytes)
06:50:06.47 [    0.584787] TCP: Hash tables configured (established 65536 bind 65536)
06:50:06.47 [    0.586365] UDP hash table entries: 4096 (order: 5, 131072 bytes)
06:50:06.47 [    0.587280] UDP-Lite hash table entries: 4096 (order: 5, 131072 bytes)
06:50:06.47 [    0.588301] NET: Registered protocol family 1
06:50:06.47 [    0.588906] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
06:50:06.47 [    0.589771] PCI: CLS 0 bytes, default 64
06:50:06.47 [    0.589822] Unpacking initramfs...
06:50:06.47 [    2.771225] Freeing initrd memory: 21648K (ffff8800355a8000 - ffff880036acc000)
06:50:06.47 [    2.772525] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
06:50:06.47 [    2.773581] software IO TLB [mem 0xbbffd000-0xbfffd000] (64MB) mapped at [ffff8800bbffd000-ffff8800bfffcfff]
06:50:06.47 [    2.775176] RAPL PMU detected, API unit is 2^-32 Joules, 3 fixed counters 10737418240 ms ovfl timer
06:50:06.47 [    2.776448] hw unit of domain pp0-core 2^-0 Joules
06:50:06.47 [    2.777140] hw unit of domain package 2^-0 Joules
06:50:06.47 [    2.777803] hw unit of domain dram 2^-0 Joules
06:50:06.47 [    2.778525] Scanning for low memory corruption every 60 seconds
06:50:06.47 [    2.779733] audit: initializing netlink subsys (disabled)
06:50:06.47 [    2.780573] audit: type=2000 audit(1510209785.240:1): initialized
06:50:06.47 [    2.781659] Initialise system trusted keyring
06:50:06.47 [    2.782539] HugeTLB registered 1 GB page size, pre-allocated 0 pages
06:50:06.47 [    2.783585] HugeTLB registered 2 MB page size, pre-allocated 0 pages
06:50:06.47 [    2.785686] zbud: loaded
06:50:06.47 [    2.786302] VFS: Disk quotas dquot_6.6.0
06:50:06.47 [    2.787027] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
06:50:06.47 [    2.788277] squashfs: version 4.0 (2009/01/31) Phillip Lougher
06:50:06.47 [    2.789439] fuse init (API version 7.23)
06:50:06.47 [    2.790153] Key type big_key registered
06:50:06.47 [    2.790729] Allocating IMA MOK and blacklist keyrings.
06:50:06.47 [    2.791803] Key type asymmetric registered
06:50:06.47 [    2.792401] Asymmetric key parser 'x509' registered
06:50:06.47 [    2.793113] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
06:50:06.47 [    2.794325] io scheduler noop registered
06:50:06.47 [    2.794959] io scheduler deadline registered (default)
06:50:06.47 [    2.795701] io scheduler cfq registered
06:50:06.47 [    2.796403] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
06:50:06.47 [    2.797228] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
06:50:06.47 [    2.798256] intel_idle: does not run on family 6 model 45
06:50:06.47 [    2.798319] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
06:50:06.47 [    2.799422] ACPI: Power Button [PWRF]
06:50:06.47 [    2.800055] input: Sleep Button as /devices/LNXSYSTM:00/LNXSLPBN:00/input/input1
06:50:06.47 [    2.801065] ACPI: Sleep Button [SLPF]
06:50:06.47 [    2.801810] GHES: HEST is not enabled!
06:50:06.47 [    2.803935] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
06:50:06.47 [    2.804767] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
06:50:06.47 [    2.808986] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 10
06:50:06.47 [    2.809875] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
06:50:06.47 [    2.814218] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
06:50:06.47 [    2.836456] 00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
06:50:06.47 [    2.859565] 00:04: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
06:50:06.47 [    2.882314] 00:05: ttyS2 at I/O 0x3e8 (irq = 6, base_baud = 115200) is a 16550A
06:50:06.47 [    2.904968] 00:06: ttyS3 at I/O 0x2e8 (irq = 7, base_baud = 115200) is a 16550A
06:50:06.47 [    2.907782] Linux agpgart interface v0.103
06:50:06.47 [    2.909893] loop: module loaded
06:50:06.47 [    2.910594] libphy: Fixed MDIO Bus: probed
06:50:06.47 [    2.911389] tun: Universal TUN/TAP device driver, 1.6
06:50:06.47 [    2.912074] tun: (C) 1999-2004 Max Krasnyansky <[email protected]>
06:50:06.47 [    2.940702] PPP generic driver version 2.4.2
06:50:06.47 [    2.941499] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
06:50:06.47 [    2.942479] ehci-pci: EHCI PCI platform driver
06:50:06.47 [    2.943213] ehci-platform: EHCI generic platform driver
06:50:06.47 [    2.943849] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
06:50:06.47 [    2.944654] ohci-pci: OHCI PCI platform driver
06:50:06.47 [    2.945303] ohci-platform: OHCI generic platform driver
06:50:06.47 [    2.946182] uhci_hcd: USB Universal Host Controller Interface driver
06:50:06.47 [    2.946966] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
06:50:06.47 [    2.949089] i8042: Warning: Keylock active
06:50:06.47 [    2.950548] serio: i8042 KBD port at 0x60,0x64 irq 1
06:50:06.47 [    2.951390] serio: i8042 AUX port at 0x60,0x64 irq 12
06:50:06.47 [    2.952203] mousedev: PS/2 mouse device common for all mice
06:50:06.47 [    2.953289] rtc_cmos 00:00: RTC can wake from S4
06:50:06.47 [    2.954113] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0
06:50:06.47 [    2.955435] rtc_cmos 00:00: alarms up to one day, 114 bytes nvram
06:50:06.47 [    2.956449] i2c /dev entries driver
06:50:06.47 [    2.957287] device-mapper: uevent: version 1.0.3
06:50:06.47 [    2.958146] device-mapper: ioctl: 4.34.0-ioctl (2015-10-28) initialised: [email protected]
06:50:06.47 [    2.959822] ledtrig-cpu: registered to indicate activity on CPUs
06:50:06.47 [    2.961228] NET: Registered protocol family 10
06:50:06.47 [    2.961990] NET: Registered protocol family 17
06:50:06.47 [    2.962645] Key type dns_resolver registered
06:50:06.47 [    2.963647] microcode: CPU0 sig=0x206d7, pf=0x1, revision=0x1
06:50:06.47 [    2.964613] microcode: CPU1 sig=0x206d7, pf=0x1, revision=0x1
06:50:06.47 [    2.966004] microcode: Microcode Update Driver: v2.01 <[email protected]>, Peter Oruba
06:50:06.47 [    2.967696] registered taskstats version 1
06:50:06.47 [    2.968380] Loading compiled-in X.509 certificates
06:50:06.47 [    2.969842] Loaded X.509 cert 'Build time autogenerated kernel key: edb476a8777da943159b94e658ffa41a270913b7'
06:50:06.47 [    2.971882] zswap: loaded using pool lzo/zbud
06:50:06.47 [    2.974181] Key type trusted registered
06:50:06.47 [    2.977210] Key type encrypted registered
06:50:06.47 [    2.977951] ima: No TPM chip found, activating TPM-bypass!
06:50:06.47 [    2.978719] evm: HMAC attrs: 0x1
06:50:06.47 [    2.979459]   Magic number: 9:26:721
06:50:06.47 [    2.980306] block loop1: hash matches
06:50:06.47 [    2.981313] rtc_cmos 00:00: setting system clock to 2017-11-09 06:43:05 UTC (1510209785)
06:50:06.47 [    2.982825] BIOS EDD facility v0.16 2004-Jun-25, 0 devices found
06:50:06.47 [    2.983522] EDD information not available.
06:50:06.47 [    2.984328] PM: Hibernation image not present or could not be loaded.
06:50:06.47 [    2.985557] Freeing unused kernel memory: 1496K (ffffffff81f48000 - ffffffff820be000)
06:50:06.47 [    2.986786] Write protecting the kernel read-only data: 14336k
06:50:06.47 [    2.988300] Freeing unused kernel memory: 1960K (ffff880001816000 - ffff880001a00000)
06:50:06.47 [    2.989662] Freeing unused kernel memory: 92K (ffff880001de9000 - ffff880001e00000)
06:50:06.47 [    3.000886] systemd-udevd[108]: starting version 204
06:50:06.47 [    3.035366] scsi host0: Virtio SCSI HBA
06:50:06.47 [    3.037560] scsi 0:0:1:0: Direct-Access     Google   PersistentDisk   1    PQ: 0 ANSI: 6
06:50:06.47 [    3.048897] AVX version of gcm_enc/dec engaged.
06:50:06.47 [    3.049609] AES CTR mode by8 optimization enabled
06:50:06.47 [    3.078475] sd 0:0:1:0: [sda] 62914560 512-byte logical blocks: (32.2 GB/30.0 GiB)
06:50:06.47 [    3.078489] sd 0:0:1:0: Attached scsi generic sg0 type 0
06:50:06.47 [    3.080413] sd 0:0:1:0: [sda] 4096-byte physical blocks
06:50:06.47 [    3.081399] sd 0:0:1:0: [sda] Write Protect is off
06:50:06.47 [    3.082048] sd 0:0:1:0: [sda] Mode Sense: 1f 00 00 08
06:50:06.47 [    3.082094] sd 0:0:1:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
06:50:06.47 [    3.085731]  sda: sda1
06:50:06.47 [    3.086641] sd 0:0:1:0: [sda] Attached SCSI disk
06:50:06.47 [    3.151167] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input2
06:50:06.47 [    3.775010] tsc: Refined TSC clocksource calibration: 2599.784 MHz
06:50:06.47 [    3.776072] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x25796fd6a1f, max_idle_ns: 440795246377 ns
06:50:06.47 [    3.984392] input: ImPS/2 Generic Wheel Mouse as /devices/platform/i8042/serio1/input/input4
06:50:06.47 [    6.071067] floppy0: no floppy controllers found
06:50:06.47 [    7.218924] raid6: sse2x1   gen()  9055 MB/s
06:50:06.47 [    7.286925] raid6: sse2x1   xor()  6256 MB/s
06:50:06.47 [    7.354922] raid6: sse2x2   gen()  9917 MB/s
06:50:06.47 [    7.422916] raid6: sse2x2   xor()  7585 MB/s
06:50:06.47 [    7.490917] raid6: sse2x4   gen() 12588 MB/s
06:50:06.47 [    7.558926] raid6: sse2x4   xor()  5508 MB/s
06:50:06.47 [    7.559801] raid6: using algorithm sse2x4 gen() 12588 MB/s
06:50:06.47 [    7.560694] raid6: .... xor() 5508 MB/s, rmw enabled
06:50:06.47 [    7.561374] raid6: using ssse3x2 recovery algorithm
06:50:06.47 [    7.563758] xor: automatically using best checksumming function:
06:50:06.47 [    7.602928]    avx       : 14912.000 MB/sec
06:50:06.47 [    7.623648] Btrfs loaded
06:50:06.47 [    7.670295] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
06:50:06.47 [    7.947883] random: init: uninitialized urandom read (12 bytes read, 24 bits of entropy available)
06:50:06.47 [    8.085552] random: mountall: uninitialized urandom read (12 bytes read, 31 bits of entropy available)
06:50:06.47 [    8.151146] EXT4-fs (sda1): re-mounted. Opts: (null)
06:50:06.47 [    8.326752] random: cloud-init: uninitialized urandom read (32 bytes read, 39 bits of entropy available)
06:50:06.47 [    8.956065] random: cloud-init: uninitialized urandom read (32 bytes read, 47 bits of entropy available)
06:50:06.47 [    9.117779] systemd-udevd[684]: starting version 204
06:50:06.47 [    9.240380] piix4_smbus 0000:00:01.3: SMBus base address uninitialized - upgrade BIOS or use force_addr=0xaddr
06:50:06.47 [    9.283200] intel_rapl: no valid rapl domains found in package 0
06:50:06.47 [    9.380590] ppdev: user-space parallel port driver
06:50:06.47 [    9.410860] random: mktemp: uninitialized urandom read (6 bytes read, 58 bits of entropy available)
06:50:06.47 [    9.470323] random: mktemp: uninitialized urandom read (6 bytes read, 61 bits of entropy available)
06:50:06.47 [    9.550291] random: cloud-init: uninitialized urandom read (32 bytes read, 61 bits of entropy available)
06:50:06.47 [    9.944186] random: cloud-init: uninitialized urandom read (32 bytes read, 61 bits of entropy available)
06:50:06.47 [   10.468968] random: mktemp: uninitialized urandom read (12 bytes read, 65 bits of entropy available)
06:50:06.47 [   10.519773] random: head: uninitialized urandom read (64 bytes read, 66 bits of entropy available)
06:50:06.47 [   12.295000] floppy0: no floppy controllers found
06:50:06.47 [   18.382282] EXT4-fs (sda1): resizing filesystem from 3931904 to 7864064 blocks
06:50:06.47 [   18.408589] EXT4-fs (sda1): resized filesystem to 7864064
06:50:06.47 [   18.778623] init: failsafe main process (1122) killed by TERM signal
06:50:06.47 [   20.126330] aufs 4.x-rcN-20160111
06:50:06.47 [   20.202676] bridge: automatic filtering via arp/ip/ip6tables has been deprecated. Update your scripts to load br_netfilter if you need this.
06:50:06.47 [   20.208279] Bridge firewalling registered
06:50:06.47 [   20.234607] nf_conntrack version 0.5.0 (65536 buckets, 262144 max)
06:50:06.47 [   20.273565] ip_tables: (C) 2000-2006 Netfilter Core Team
06:50:06.47 [   20.447540] Initializing XFRM netlink socket
06:50:06.47 [   20.760456] aufs au_opts_verify:1597:dockerd[1419]: dirperm1 breaks the protection by the permission bits on the lower branch
06:50:06.47 [   21.157206] random: nonblocking pool is initialized
06:50:06.47 [   26.500634] postgres (1790): /proc/1790/oom_adj is deprecated, please use /proc/1790/oom_score_adj instead.
06:50:06.47 [   28.579329] ip6_tables: (C) 2000-2006 Netfilter Core Team
06:50:06.47 [   28.786284] init: plymouth-upstart-bridge main process ended, respawning
06:50:06.47 [   60.758414] systemd-udevd[9365]: starting version 204
06:50:06.47 [   64.308721] init: Failed to obtain startpar-bridge instance: Unknown parameter: INSTANCE
06:50:06.47 [   65.023923] FS-Cache: Loaded
06:50:06.47 [   65.033644] RPC: Registered named UNIX socket transport module.
06:50:06.47 [   65.033648] RPC: Registered udp transport module.
06:50:06.47 [   65.033649] RPC: Registered tcp transport module.
06:50:06.47 [   65.033650] RPC: Registered tcp NFSv4.1 backchannel transport module.
06:50:06.47 [   65.050327] FS-Cache: Netfs 'nfs' registered for caching
06:50:06.47 [   65.064151] Installing knfsd (copyright (C) 1996 [email protected]).
06:50:06.47 [  414.537391] spl: module verification failed: signature and/or required key missing - tainting kernel
06:50:06.47 [  414.540767] SPL: Loaded module v0.7.0-1
06:50:06.47 [  414.548512] SPLAT: Loaded module v0.7.0-1
06:50:06.47 [  414.553704] zavl: module license 'CDDL' taints kernel.
06:50:06.47 [  414.553708] Disabling lock debugging due to kernel taint
06:50:06.47 [  416.186441] ZFS: Loaded module v0.7.0-1, ZFS pool version 5000, ZFS filesystem version 5
06:50:06.47 [  416.260474] intel_rapl: no valid rapl domains found in package 0
06:50:06.47 [  419.252096] floppy0: no floppy controllers found
06:50:06.47 [  420.749721] intel_rapl: no valid rapl domains found in package 0
06:50:06.47 [  423.732142] floppy0: no floppy controllers found
06:50:06.47 =================================================================
06:50:06.47  End of dmesg log
06:50:06.47 =================================================================
06:50:06.48 NOTE: Performing test-fail callback (/home/travis/build/gmelikov/zfs/tests/zfs-tests/callbacks/zfs_mmp.ksh)
06:50:06.48 NOTE: Performing local cleanup via log_onexit (cleanup_testenv)
06:50:06.61 SUCCESS: zfs destroy -Rf testpool/testctr

Travis builders have maximum work time ~49 minutes,
so we have to use 5 builders.

Signed-off-by: George Melikov <[email protected]>
@gmelikov
Copy link
Member Author

It's ready to merge, 2 last builds are successful: https://travis-ci.org/gmelikov/zfs/builds/301000827 https://travis-ci.org/gmelikov/zfs/builds/300975940

@behlendorf behlendorf merged commit 13042a6 into openzfs:master Nov 13, 2017
Nasf-Fan pushed a commit to Nasf-Fan/zfs that referenced this pull request Jan 29, 2018
Travis builders have maximum work time ~49 minutes,
so we have to use 5 builders and spread the ZTS over
them using test group tags.

Reviewed-by: Brian Behlendorf <[email protected]>
Reviewed-by: Giuseppe Di Natale <[email protected]>
Signed-off-by: George Melikov <[email protected]>
Closes openzfs#6829
Nasf-Fan pushed a commit to Nasf-Fan/zfs that referenced this pull request Feb 13, 2018
Travis builders have maximum work time ~49 minutes,
so we have to use 5 builders and spread the ZTS over
them using test group tags.

Reviewed-by: Brian Behlendorf <[email protected]>
Reviewed-by: Giuseppe Di Natale <[email protected]>
Signed-off-by: George Melikov <[email protected]>
Closes openzfs#6829
FransUrbo pushed a commit to FransUrbo/zfs that referenced this pull request Apr 28, 2019
Travis builders have maximum work time ~49 minutes,
so we have to use 5 builders and spread the ZTS over
them using test group tags.

Reviewed-by: Brian Behlendorf <[email protected]>
Reviewed-by: Giuseppe Di Natale <[email protected]>
Signed-off-by: George Melikov <[email protected]>
Closes openzfs#6829
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

Successfully merging this pull request may close these issues.

4 participants