[#LU-1205] sanityn.sh test_18 mmap_sanity sometimes takes thousands of seconds to run

[LU-1205] sanityn.sh test_18 mmap_sanity sometimes takes thousands of seconds to run Created: 12/Mar/12 Updated: 23/Oct/17 Resolved: 22/May/12
Status:	Resolved
Project:	Lustre
Component/s:	None
Affects Version/s:	Lustre 2.2.0, Lustre 2.3.0, Lustre 2.1.1
Fix Version/s:	Lustre 2.3.0, Lustre 2.1.2

Type:

Bug

Priority:

Blocker

Reporter:

Andreas Dilger

Assignee:

Jinshan Xiong (Inactive)

Resolution:

Fixed

Votes:

Labels:

None

Issue Links:

Duplicate
is duplicated by	~~LU-1393~~	Test failure on test suite sanityn te...	Resolved
Related
is related to	~~LU-10149~~	sanityn test_23: timeout after test_1...	Resolved

Story Points:

Severity:

Rank (Obsolete):

4230

Description

Looking through the test history for sanity.sh subtest_18 it appears that the runtime of this test varies by a huge amount. Sometimes it is completing in as few as 6s or over 3600s, and sometimes failing with a timeout or causing one of the later sanityn.sh tests to time out instead.

The timeouts happen most often on the orion branch, but long test runs also happen on master review.

Name 	Status 	Run at 				Duration
test_18 PASS 	2012-03-12 14:22:06 UTC 	13
test_18 PASS 	2012-03-12 11:28:53 UTC 	3800
test_18 PASS 	2012-03-12 07:57:47 UTC 	9
test_18 PASS 	2012-03-12 06:51:38 UTC 	15
test_18 PASS 	2012-03-12 06:39:20 UTC 	436
test_18 PASS 	2012-03-12 05:55:11 UTC 	90
test_18 PASS 	2012-03-12 04:43:36 UTC 	8
test_18 PASS 	2012-03-12 03:54:46 UTC 	52
test_18 PASS 	2012-03-12 01:18:41 UTC 	85
test_18 PASS 	2012-03-12 00:34:43 UTC 	1323
test_18 PASS 	2012-03-12 00:34:43 UTC 	1323
test_18 TIMEOUT 2012-03-12 00:25:14 UTC 	3600
test_18 TIMEOUT 2012-03-11 22:52:26 UTC 	3600
test_18 PASS 	2012-03-11 22:26:00 UTC 	49
test_18 TIMEOUT 2012-03-11 20:35:55 UTC 	3600
test_18 PASS 	2012-03-11 20:30:23 UTC 	3778
test_18 PASS 	2012-03-11 19:01:24 UTC 	24
test_18 PASS 	2012-03-11 15:19:46 UTC 	169
test_18 PASS 	2012-03-11 14:58:48 UTC 	6
test_18 PASS 	2012-03-11 14:16:18 UTC 	10
test_18 PASS 	2012-03-11 13:40:19 UTC 	2249
test_18 PASS 	2012-03-11 12:29:16 UTC 	334
test_18 PASS 	2012-03-11 12:03:12 UTC 	115
test_18 PASS 	2012-03-11 11:06:46 UTC 	612
test_18 PASS 	2012-03-11 10:23:40 UTC 	16
test_18 TIMEOUT 2012-03-11 07:18:33 UTC 	3600
test_18 PASS 	2012-03-11 06:03:44 UTC 	26
test_18 PASS 	2012-03-11 06:01:00 UTC 	123
test_18 PASS 	2012-03-11 04:58:09 UTC 	105
test_18 PASS 	2012-03-11 01:38:42 UTC 	30

Info required for matching: sanityn 18

Comments

Comment by Brian Murrell (Inactive) [ 12/Mar/12 ]

FWIW, in ltest (a previous incarnation of Lustre testing), a test was marked a failure (even if the test itself was a pass – or maybe it was a "warning") if any single run time to exceed some given threshold beyond the stddev of the past $n successful test runs.

This forced the investigation of wildly varying test results such as is documented here.

Comment by Andreas Dilger [ 12/Mar/12 ]

For orion: http://review.whamcloud.com/2289
For master: http://review.whamcloud.com/2290
Whitespace cleanup: http://review.whamcloud.com/2291

Comment by Andreas Dilger [ 12/Mar/12 ]

The above patches are for debugging the time taken by the sub-parts of this test. I don't yet know why the test takes so long.

Comment by Andreas Dilger [ 15/Mar/12 ]

A successful run on master looks like:
https://maloo.whamcloud.com/sub_tests/8afa6070-6d2c-11e1-9174-5254004bbbd3

== sanityn test 18: mmap sanity check == 03:05:41 (1331633141)
mmap test1: basic mmap operation (PASS, 0.021068s)
mmap test2: MAP_PRIVATE not write back (PASS, 0.012644s)
mmap test3: concurrent mmap ops on two nodes (PASS, 3.3153s)
mmap test4: c1 write to f1 from mmapped f2, c2 write to f1 from mmapped f1 (PASS, 2.1067s)
mmap test5: read/write file to/from the buffer which mmapped to just this file (PASS, 0.039092s)
mmap test6: check mmap write/read content on two nodes (PASS, 0.11611s)
mmap test7: file i/o with an unmapped buffer (PASS, 0.063589s)
mmap test8: SIGBUS for beyond file size (PASS, 0.00761s)
Resetting fail_loc on all nodes...done.

An unsuccessful run on Orion looks like:
https://maloo.whamcloud.com/test_sets/285b1a18-6dc7-11e1-9d47-5254004bbbd3

== sanityn test 18: mmap sanity check ================================================================ 06:07:36 (1331644056)
mmap test1: basic mmap operation (PASS, 0.028616s)
mmap test2: MAP_PRIVATE not write back (PASS, 0.01381s)

at which point the client is hung and the mmap process does not appear in the stack dumps.

Comment by Mikhail Pershin [ 09/Apr/12 ]

bug exists in master for a long time, the first occurrence I've found is November, 2011:

https://maloo.whamcloud.com/test_sets/433b98bc-178c-11e1-8f40-52540025f9af

it appeared in Orion only in February, 2012:
https://maloo.whamcloud.com/test_sets/b93b52f4-5df6-11e1-8401-5254004bbbd3

but that can be non-reliable as test 16 failed in Orion quite often at that time and may hide test 18 issue.