[LU-6029] conf-sanity test_84: recovery_duration > recovery_time_hard

• Type: Bug
• Resolution: Fixed
• Priority: Critical
• Fix Version/s: Lustre 2.7.0
• Affects Version/s: Lustre 2.7.0
• Labels: HB zfs
• Severity: 3
• Assignee: Dmitry Eremin (Inactive)
• Reporter: Maloo

Description

This issue was created by maloo for Li Wei <[e-mail]>

This issue relates to the following test suite run: https://testing.hpdd.intel.com/test_sets/487b214e-84bc-11e4-84b4-5254006e85c2.

The sub-test test_84 failed with the following error:

recovery_duration > recovery_time_hard

More detailed test output:

[...]
recovery_time_hard 60, recovery_time_soft 60, 		timeout 20
[...]
recovery status
CMD: shadow-5vm4 /usr/sbin/lctl get_param -n 				mdt.lustre-MDT0000.recovery_status
status: COMPLETE
recovery_start: 1418671057
recovery_duration: 61
completed_clients: 1/2
replayed_requests: 202
last_transno: 8589934798
VBR: DISABLED
IR: DISABLED
CMD: shadow-5vm4 /usr/sbin/lctl get_param -n 				mdt.lustre-MDT0000.recovery_status
 conf-sanity test_84: @@@@@@ FAIL: recovery_duration > recovery_time_hard 

Info required for matching: conf-sanity 84

Issue Links

• is related to: LU-5986 conf-sanity test_83, test_84: failed to start OST
• is related to: LU-7428 conf-sanity test_84, replay-dual 0a: /dev/lvm-Role_MDS/P1 failed to initialize!

Comments

[Gerrit Updater]

Andreas Dilger ([e-mail]) merged in patch http://review.whamcloud.com/13087/
Subject: LU-6029 test: add wrap up duration in conf-sanity test_84
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: b74076ff1637cb89dbf9ebacbf3703d2dbb431b0

[Gerrit Updater]

Dmitry Eremin ([e-mail]) uploaded a new patch: http://review.whamcloud.com/13087
Subject: LU-6029 test: add wrap up duration in conf-sanity test_84
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: af47001057aa22e17cee3f2a52f0160c43271c20

[Dmitry Eremin (Inactive)]

After commit "abort recovery by time_hard" this test can fail because of long time of callbacks processing. From attached log below it spend at least 1 second inside target_finish_recovery() function and set "obd->obd_recovery_end = cfs_time_current_sec();" at the end. Therefore the recovery time always will be more than hard limit but difference depends from how long target_finish_recovery() function runs.

I suppose we should set obd_recovery_end at the beginning of this function or add additional time in test if we care about callbacks processing time also.

00010000:00000001:0.0:1418693585.999353:0:29342:0:(ldlm_lib.c:1361:target_finish_recovery()) Process entered
00010000:02000000:0.0:1418693585.999354:0:29342:0:(ldlm_lib.c:1373:target_finish_recovery()) lustre-MDT0000: Recovery over after 1:00, of 2 clients 1 recovered and 1 was evicted.
00000100:00000001:1.0:1418693585.999437:0:27052:0:(events.c:393:reply_out_callback()) Process entered
00000100:00000001:1.0:1418693585.999438:0:27052:0:(events.c:404:reply_out_callback()) Process leaving
00000020:00000001:1.0:1418693585.999445:0:27041:0:(genops.c:1681:obd_zombie_impexp_check()) Process leaving (rc=0 : 0 : 0)
00000020:00000001:1.0:1418693585.999447:0:27041:0:(genops.c:1617:obd_zombie_impexp_cull()) Process entered
00000020:00000001:1.0:1418693585.999448:0:27041:0:(genops.c:786:class_export_destroy()) Process entered
00000020:00000080:1.0:1418693585.999449:0:27041:0:(genops.c:792:class_export_destroy()) destroying export ffff88005f432400/244858c2-a0fa-d004-ee90-47650a2969ea for lustre-MDT0000
00000100:00000001:1.0:1418693585.999450:0:27041:0:(connection.c:95:ptlrpc_connection_put()) Process entered
00000100:00000040:1.0:1418693585.999452:0:27041:0:(connection.c:123:ptlrpc_connection_put()) PUT conn=ffff88006928f340 refcount 6 to 10.2.4.233@tcp
00000100:00000001:1.0:1418693585.999453:0:27041:0:(connection.c:125:ptlrpc_connection_put()) Process leaving (rc=0 : 0 : 0)
00000020:00000001:1.0:1418693585.999454:0:27041:0:(obd_class.h:1113:obd_destroy_export()) Process entered
00000004:00000001:1.0:1418693585.999455:0:27041:0:(mdt_handler.c:5288:mdt_destroy_export()) Process entered
00000020:00000040:1.0:1418693585.999456:0:27041:0:(genops.c:1007:class_import_get()) import ffff8800600c9800 refcount=2 obd=lustre-MDT0000
00000020:00000040:1.0:1418693585.999458:0:27041:0:(lustre_handles.c:116:class_handle_unhash_nolock()) removing object ffff8800600c9800 with handle 0x1f6d0c16dcfa66a3 from hash
00000020:00000001:1.0:1418693585.999459:0:27041:0:(genops.c:1014:class_import_put()) Process entered
00000020:00000040:1.0:1418693585.999460:0:27041:0:(genops.c:1021:class_import_put()) import ffff8800600c9800 refcount=1 obd=lustre-MDT0000
00000020:00000001:1.0:1418693585.999461:0:27041:0:(genops.c:1030:class_import_put()) Process leaving
00000020:00000001:1.0:1418693585.999462:0:27041:0:(genops.c:1014:class_import_put()) Process entered
00000020:00000040:1.0:1418693585.999462:0:27041:0:(genops.c:1021:class_import_put()) import ffff8800600c9800 refcount=0 obd=lustre-MDT0000
00000020:00000040:1.0:1418693585.999463:0:27041:0:(genops.c:1024:class_import_put()) final put import ffff8800600c9800
00000020:00000001:1.0:1418693585.999464:0:27041:0:(genops.c:1030:class_import_put()) Process leaving
00010000:00000001:1.0:1418693585.999466:0:27041:0:(ldlm_lockd.c:2821:ldlm_destroy_export()) Process entered
00000001:00000001:1.0:1418693585.999467:0:27041:0:(hash.c:1106:cfs_hash_destroy()) Process entered
00000001:00000010:1.0:1418693585.999469:0:27041:0:(hash.c:897:cfs_hash_buckets_free()) kfreed 'buckets[i]': 280 at ffff88005f436c00 (tot 35710677).
00000001:00000010:1.0:1418693585.999471:0:27041:0:(hash.c:897:cfs_hash_buckets_free()) kfreed 'buckets[i]': 280 at ffff88005f436a00 (tot 35710397).
00000001:00000010:1.0:1418693585.999472:0:27041:0:(hash.c:897:cfs_hash_buckets_free()) kfreed 'buckets[i]': 280 at ffff88005f436800 (tot 35710117).
00000001:00000010:1.0:1418693585.999473:0:27041:0:(hash.c:897:cfs_hash_buckets_free()) kfreed 'buckets[i]': 280 at ffff88005f436600 (tot 35709837).
00000001:00000010:1.0:1418693585.999473:0:27041:0:(hash.c:900:cfs_hash_buckets_free()) kfreed 'buckets': 32 at ffff880061c16380 (tot 35709805).
00000001:00000010:1.0:1418693585.999475:0:27041:0:(hash.c:1156:cfs_hash_destroy()) kfreed 'hs': 144 at ffff88005f431d40 (tot 35709661).
00000001:00000001:1.0:1418693585.999476:0:27041:0:(hash.c:1158:cfs_hash_destroy()) Process leaving
00010000:00000001:1.0:1418693585.999477:0:27041:0:(ldlm_flock.c:972:ldlm_destroy_flock_export()) Process entered
00000001:00000001:1.0:1418693585.999478:0:27041:0:(hash.c:1106:cfs_hash_destroy()) Process entered
00000001:00000010:1.0:1418693585.999480:0:27041:0:(hash.c:897:cfs_hash_buckets_free()) kfreed 'buckets[i]': 280 at ffff88005f436400 (tot 35709381).
00000001:00000010:1.0:1418693585.999482:0:27041:0:(hash.c:897:cfs_hash_buckets_free()) kfreed 'buckets[i]': 280 at ffff88005f436200 (tot 35709101).
00000001:00000010:1.0:1418693585.999483:0:27041:0:(hash.c:897:cfs_hash_buckets_free()) kfreed 'buckets[i]': 280 at ffff88005f436000 (tot 35708821).
00000001:00000010:1.0:1418693585.999484:0:27041:0:(hash.c:897:cfs_hash_buckets_free()) kfreed 'buckets[i]': 280 at ffff88005f439e00 (tot 35708541).
00000001:00000010:1.0:1418693585.999485:0:27041:0:(hash.c:900:cfs_hash_buckets_free()) kfreed 'buckets': 32 at ffff880061c16540 (tot 35708509).
00000001:00000010:1.0:1418693585.999486:0:27041:0:(hash.c:1156:cfs_hash_destroy()) kfreed 'hs': 144 at ffff88005f431c80 (tot 35708365).
00000001:00000001:1.0:1418693585.999498:0:27041:0:(hash.c:1158:cfs_hash_destroy()) Process leaving
00010000:00000001:1.0:1418693585.999499:0:27041:0:(ldlm_flock.c:977:ldlm_destroy_flock_export()) Process leaving
00010000:00000001:1.0:1418693585.999500:0:27041:0:(ldlm_lockd.c:2826:ldlm_destroy_export()) Process leaving
00000001:00000010:1.0:1418693585.999501:0:27041:0:(tgt_lastrcvd.c:88:tgt_client_free()) kfreed 'ted->ted_lcd': 128 at ffff88006e450bc0.
00000004:00000001:1.0:1418693585.999503:0:27041:0:(mdt_handler.c:5306:mdt_destroy_export()) Process leaving (rc=0 : 0 : 0)
00000020:00000001:1.0:1418693585.999504:0:27041:0:(obd_class.h:1117:obd_destroy_export()) Process leaving (rc=0 : 0 : 0)
00000020:00000040:1.0:1418693585.999505:0:27041:0:(obd_config.c:718:class_decref()) Decref lustre-MDT0000 (ffff88007c16c0f8) now 8
00000020:00000001:1.0:1418693585.999508:0:27041:0:(genops.c:806:class_export_destroy()) Process leaving
00000020:00000001:1.0:1418693585.999509:0:27041:0:(genops.c:967:class_import_destroy()) Process entered
00000020:00000080:1.0:1418693585.999510:0:27041:0:(genops.c:970:class_import_destroy()) destroying import ffff8800600c9800 for lustre-MDT0000
00000100:00000001:1.0:1418693585.999511:0:27041:0:(connection.c:95:ptlrpc_connection_put()) Process entered
00000100:00000040:1.0:1418693585.999534:0:27041:0:(connection.c:123:ptlrpc_connection_put()) PUT conn=ffff88006928f340 refcount 5 to 10.2.4.233@tcp
00000100:00000001:1.0:1418693585.999535:0:27041:0:(connection.c:125:ptlrpc_connection_put()) Process leaving (rc=0 : 0 : 0)
00000020:00000040:1.0:1418693585.999536:0:27041:0:(obd_config.c:718:class_decref()) Decref lustre-MDT0000 (ffff88007c16c0f8) now 7
00000020:00000001:1.0:1418693585.999538:0:27041:0:(genops.c:989:class_import_destroy()) Process leaving
00000020:00000001:1.0:1418693585.999539:0:27041:0:(genops.c:1656:obd_zombie_impexp_cull()) Process leaving
00000020:00000001:1.0:1418693585.999540:0:27041:0:(genops.c:1681:obd_zombie_impexp_check()) Process leaving (rc=1 : 1 : 1)
00000020:00000001:1.0:1418693585.999541:0:27041:0:(genops.c:1681:obd_zombie_impexp_check()) Process leaving (rc=1 : 1 : 1)
00010000:00000001:0.0:1418693586.002887:0:29342:0:(ldlm_lock.c:2027:ldlm_reprocess_all_ns()) Process entered
00000001:00000001:0.0:1418693586.002888:0:29342:0:(hash.c:1654:cfs_hash_for_each_nolock()) Process entered
00000001:00000001:0.0:1418693586.002889:0:29342:0:(hash.c:1599:cfs_hash_for_each_relax()) Process entered
00000001:00000001:0.0:1418693586.011418:0:29342:0:(hash.c:1670:cfs_hash_for_each_nolock()) Process leaving (rc=0 : 0 : 0)
00010000:00000001:0.0:1418693586.011421:0:29342:0:(ldlm_lock.c:2033:ldlm_reprocess_all_ns()) Process leaving
00000020:00000010:0.0:1418693586.011428:0:29342:0:(lu_object.c:1706:keys_init()) kmalloced 'ctx->lc_value': 320 at ffff88006c330e00.
00000020:00000010:0.0:1418693586.011430:0:29342:0:(lu_object.c:458:lu_global_key_init()) kmalloced 'value': 512 at ffff8800677a6800.
00000020:00000010:0.0:1418693586.011433:0:29342:0:(dt_object.c:55:dt_global_key_init()) kmalloced 'value': 1232 at ffff8800673f5000.
00000040:00000010:0.0:1418693586.011435:0:29342:0:(llog_obd.c:250:llog_key_init()) kmalloced 'value': 216 at ffff880078e315c0.
00000020:00000010:0.0:1418693586.011437:0:29342:0:(tgt_main.c:147:tgt_key_init()) kmalloced 'value': 1168 at ffff880061211800.
80000000:00000010:0.0:1418693586.011439:0:29342:0:(fld_handler.c:59:fld_key_init()) kmalloced 'value': 72 at ffff880072046240.
40000000:00000010:0.0:1418693586.011441:0:29342:0:(fid_handler.c:404:seq_key_init()) kmalloced 'value': 48 at ffff88005ec3a840.
00040000:00000010:0.0:1418693586.011444:0:29342:0:(lquota_lib.c:53:lquota_key_init()) kmalloced 'value': 240 at ffff880063929880.
00040000:00000010:0.0:1418693586.011445:0:29342:0:(qmt_dev.c:341:qmt_key_init()) kmalloced 'value': 376 at ffff880068277400.
00040000:00000010:0.0:1418693586.011447:0:29342:0:(qsd_lib.c:71:qsd_key_init()) kmalloced 'value': 376 at ffff880037b3c200.
00080000:00000010:0.0:1418693586.011449:0:29342:0:(osd_handler.c:631:osd_key_init()) kmalloced 'info': 1576 at ffff8800693cc800.
00100000:00000010:0.0:1418693586.011451:0:29342:0:(lfsck_lib.c:48:lfsck_key_init()) kmalloced 'value': 1680 at ffff880065737000.
00000004:00000010:0.0:1418693586.011453:0:29342:0:(mdt_handler.c:5899:mdt_key_init()) kmalloced 'value': 1456 at ffff8800665d8800.
00000004:00000010:0.0:1418693586.011456:0:29342:0:(lod_dev.c:1071:lod_key_init()) kmalloced 'value': 696 at ffff88006d0df400.
00000004:00000010:0.0:1418693586.011464:0:29342:0:(mdd_device.c:1545:mdd_key_init()) kmalloced 'value': 1608 at ffff88005dd13000.
00000004:00000010:0.0:1418693586.011466:0:29342:0:(osp_dev.c:1671:osp_key_init()) kmalloced 'value': 568 at ffff88006d735800.
00000004:00000001:0.0:1418693586.011468:0:29342:0:(mdt_handler.c:5813:mdt_postrecov()) Process entered
00000004:00000001:0.0:1418693586.011469:0:29342:0:(mdd_device.c:1456:mdd_iocontrol()) Process entered
00100000:00000001:0.0:1418693586.011470:0:29342:0:(lfsck_lib.c:2618:lfsck_start()) Process entered
00100000:00000001:0.0:1418693586.011471:0:29342:0:(lfsck_lib.c:2632:lfsck_start()) Process leaving via put (rc=0 : 0 : 0x0)
00000004:00000001:0.0:1418693586.011472:0:29342:0:(mdd_device.c:1476:mdd_iocontrol()) Process leaving (rc=0 : 0 : 0)
00000004:00000001:0.0:1418693586.011474:0:29342:0:(mdd_device.c:921:mdd_recovery_complete()) Process entered
00000004:00000010:0.0:1418693586.011475:0:29342:0:(mdd_orphans.c:601:mdd_orphan_cleanup()) kmalloced 'name': 64 at ffff88005ec3a640.
00000004:00000001:0.0:1418693586.011718:0:29544:0:(mdd_orphans.c:569:__mdd_orphan_cleanup()) Process entered
00000004:00000010:0.0:1418693586.011721:0:29342:0:(mdd_orphans.c:615:mdd_orphan_cleanup()) kfreed 'name': 64 at ffff88005ec3a640.
00000004:00000001:0.0:1418693586.011723:0:29342:0:(lod_dev.c:454:lod_recovery_complete()) Process entered
00080000:00000001:0.0:1418693586.011725:0:29342:0:(osd_handler.c:1031:osd_recovery_complete()) Process entered
00040000:00000001:0.0:1418693586.011726:0:29342:0:(qsd_lib.c:769:qsd_start()) Process entered
00040000:00000001:0.0:1418693586.011727:0:29342:0:(qsd_lib.c:798:qsd_start()) Process leaving (rc=0 : 0 : 0)
00080000:00000001:0.0:1418693586.011728:0:29342:0:(osd_handler.c:1039:osd_recovery_complete()) Process leaving (rc=0 : 0 : 0)
00000004:00000001:0.0:1418693586.011730:0:29342:0:(osp_dev.c:594:osp_recovery_complete()) Process entered
00000004:00000001:0.0:1418693586.011732:0:29342:0:(osp_dev.c:600:osp_recovery_complete()) Process leaving (rc=0 : 0 : 0)
00000004:00000001:0.0:1418693586.011733:0:29342:0:(osp_dev.c:594:osp_recovery_complete()) Process entered
00000004:00000001:0.0:1418693586.011744:0:29342:0:(osp_dev.c:600:osp_recovery_complete()) Process leaving (rc=0 : 0 : 0)
00000004:00000001:0.0:1418693586.011745:0:29342:0:(lod_dev.c:475:lod_recovery_complete()) Process leaving (rc=0 : 0 : 0)
00000004:00000001:0.0:1418693586.011746:0:29342:0:(mdd_device.c:930:mdd_recovery_complete()) Process leaving (rc=0 : 0 : 0)
00000004:00000001:0.0:1418693586.011747:0:29342:0:(mdt_handler.c:5825:mdt_postrecov()) Process leaving (rc=0 : 0 : 0)
00000020:00000010:0.0:1418693586.011750:0:29342:0:(lu_object.c:458:lu_global_key_fini()) kfreed 'info': 512 at ffff8800677a6800.
00000020:00000010:0.0:1418693586.011752:0:29342:0:(dt_object.c:56:dt_global_key_fini()) kfreed 'info': 1232 at ffff8800673f5000.
00000040:00000010:0.0:1418693586.011753:0:29342:0:(llog_obd.c:250:llog_key_fini()) kfreed 'info': 216 at ffff880078e315c0.
00000020:00000010:0.0:1418693586.011755:0:29342:0:(tgt_main.c:164:tgt_key_fini()) kfreed 'info': 1168 at ffff880061211800.
80000000:00000010:0.0:1418693586.011756:0:29342:0:(fld_handler.c:59:fld_key_fini()) kfreed 'info': 72 at ffff880072046240.
40000000:00000010:0.0:1418693586.011757:0:29342:0:(fid_handler.c:404:seq_key_fini()) kfreed 'info': 48 at ffff88005ec3a840.
00040000:00000010:0.0:1418693586.011759:0:29342:0:(lquota_lib.c:53:lquota_key_fini()) kfreed 'info': 240 at ffff880063929880.
00040000:00000010:0.0:1418693586.011760:0:29342:0:(qmt_dev.c:341:qmt_key_fini()) kfreed 'info': 376 at ffff880068277400.
00040000:00000010:0.0:1418693586.011761:0:29342:0:(qsd_lib.c:71:qsd_key_fini()) kfreed 'info': 376 at ffff880037b3c200.
00080000:00000010:0.0:1418693586.011762:0:29342:0:(osd_handler.c:644:osd_key_fini()) kfreed 'info': 1576 at ffff8800693cc800.
00100000:00000010:0.0:1418693586.011763:0:29342:0:(lfsck_lib.c:58:lfsck_key_fini()) kfreed 'info': 1680 at ffff880065737000.
00000004:00000010:0.0:1418693586.011765:0:29342:0:(mdt_handler.c:5911:mdt_key_fini()) kfreed 'info': 1456 at ffff8800665d8800.
00000004:00000010:0.0:1418693586.011766:0:29342:0:(lod_dev.c:1087:lod_key_fini()) kfreed 'info': 696 at ffff88006d0df400.
00000004:00000010:0.0:1418693586.011768:0:29342:0:(mdd_device.c:1555:mdd_key_fini()) kfreed 'info': 1608 at ffff88005dd13000.
00000004:00000010:0.0:1418693586.011769:0:29342:0:(osp_dev.c:1671:osp_key_fini()) kfreed 'info': 568 at ffff88006d735800.
00000020:00000010:0.0:1418693586.011770:0:29342:0:(lu_object.c:1656:keys_fini()) kfreed 'ctx->lc_value': 320 at ffff88006c330e00.
00010000:00000001:0.0:1418693586.011771:0:29342:0:(ldlm_lib.c:1402:target_finish_recovery()) Process leaving