Re: kern/47563: test cases do not timeout and hang

[Martin Husemann <martin%duskware.de@localhost>]

The following reply was made to PR kern/47563; it has been noted by GNATS.

From: Martin Husemann <martin%duskware.de@localhost>
To: gnats-bugs%NetBSD.org@localhost
Cc: Antti Kantee <pooka%NetBSD.org@localhost>, Julio Merino 
<jmmv%NetBSD.org@localhost>
Subject: Re: kern/47563: test cases do not timeout and hang
Date: Fri, 15 Feb 2013 17:32:43 +0100

 A bit more data: I can reproduce the failure on various sparc64 SMP
 machines. It seems to not affect the uniprocessor automatic test runs
 (including the sparc ones), and seems to not be reproducable on x86.
 
 The test case, when run as "atf-test t_swsensor" alone, does not output
 anything exciting:
 
 ...
 tps-count: 1
 tp-start: 1360944907.365325, t_swsensor, 5
 tc-start: 1360944907.365395, alarm_sensor
 
 ... and there i hangs untill I manually kill rump_allserver. A ktrace shows
 not a lot activity (and neither the rump process nor atf-run gather a lot
 of cpu usage):
 
   2765     12 rump_allserver CALL  
___lwp_park50(0x49f158e8,0,0x4a504098,0x4a50$
   2765      6 rump_allserver RET   ___lwp_park50 -1 errno 60 Connection timed 
o$
   2765      1 rump_allserver RET   __nanosleep50 0, -87720/0xfffffffffffea958  
 
   2765      1 rump_allserver CALL  _lwp_unpark(7,0x48830998)
   2765      6 rump_allserver CALL  
___lwp_park50(0x493096e8,0,0x4c204098,0x4c20$
   2765      6 rump_allserver RET   ___lwp_park50 -1 errno 60 Connection timed 
o$
   2765      1 rump_allserver RET   _lwp_unpark 0, 1216547224/0x48830998
   2765      6 rump_allserver CALL  
___lwp_park50(0x493096e8,0,0x4c204098,0x4c20$
   2765      1 rump_allserver CALL  _lwp_unpark_all(0x482109f8,1,0x48830698)
   2765      1 rump_allserver RET   _lwp_unpark_all 0, 1
   2765      7 rump_allserver RET   ___lwp_park50 0
   2765      1 rump_allserver CALL  ___lwp_park50(0,0,0x488309d8,0x488309d8)
   2765      9 rump_allserver RET   ___lwp_park50 0
   2765      7 rump_allserver CALL  _lwp_unpark_all(0x4885e0f8,1,0x48830618)
   2765      7 rump_allserver RET   _lwp_unpark_all 0, 1
   2765      9 rump_allserver CALL  ___lwp_park50(0,0,0x48830698,0x48830698)
   2765      7 rump_allserver CALL  ___lwp_park50(0,0,0x48830998,0x48830998)
   2765      3 rump_allserver RET   ___lwp_park50 0
   2765      3 rump_allserver CALL  _lwp_unpark(1,0x488309d8)
   2765      3 rump_allserver RET   _lwp_unpark 0, 1216547288/0x488309d8
  
 and sometimes a timeout on the atf-run side:
 
   2765      1 rump_allserver CALL  
__nanosleep50(0xfffffffffffea968,0xfffffffff$
   2765     12 rump_allserver RET   ___lwp_park50 -1 errno 60 Connection timed 
o$
   2483      1 atf-run  RET   poll 0, 2
   2765     12 rump_allserver CALL  
___lwp_park50(0x49f158e8,0,0x4a504098,0x4a50$
   2765     12 rump_allserver RET   ___lwp_park50 -1 errno 60 Connection timed 
o$
   2483      1 atf-run  CALL  poll(0x413120a0,2,0xfa)   
   2765     12 rump_allserver CALL  
___lwp_park50(0x49f158e8,0,0x4a504098,0x4a50$
   2765      1 rump_allserver RET   __nanosleep50 0, -87720/0xfffffffffffea958
 
 
 This makes it even more interesting that atf-run does not seem to timeout
 the testcase after 60 seconds.
 
 The atf-run process is in:
 
 #0  0x000000000011de30 in atf::atf_run::muxer::read_one(unsigned long, int, 
std::string&, bool) ()
 #1  0x000000000011e23c in atf::atf_run::muxer::flush() ()
 #2  0x0000000000129a98 in atf::atf_run::run_test_case(atf::fs::path const&, 
std::string const&, std::string const&, std::map<std::string, std::string, 
std::less<std::string>, std::allocator<std::pair<std::string const, 
std::string> > > const&, std::map<std::string, std::string, 
std::less<std::string>, std::allocator<std::pair<std::string const, 
std::string> > > const&, atf::fs::path const&, atf::fs::path const&, 
atf::atf_run::atf_tps_writer&) ()
 #3  0x000000000010ba98 in atf_run::run_test_program(atf::fs::path const&, 
atf::atf_run::atf_tps_writer&, std::map<std::string, std::string, 
std::less<std::string>, std::allocator<std::pair<std::string const, 
std::string> > > const&) ()
 #4  0x000000000010dab4 in atf_run::run_test(atf::fs::path const&, 
atf::atf_run::atf_tps_writer&, std::map<std::string, std::string, 
std::less<std::string>, std::allocator<std::pair<std::string const, 
std::string> > > const&) ()
 #5  0x000000000010df0c in atf_run::main() ()
 #6  0x000000004052c190 in atf::application::app::run(int, char* const*) ()
    from /usr/lib/libatf-c++.so.0
 #7  0x0000000000107ea0 in main ()
 
 Unfortunately gdb is non-cooperative for the rump_allserver process - guess
 I'll look at that first now ;-)
 
 Martin