All of lore.kernel.org
 help / color / mirror / Atom feed
From: Maksym Veremeyenko <verem@domain.hid>
To: Xenomai-help@domain.hid
Subject: Re: [Xenomai-help] Strange deadlock.
Date: Sat, 10 Feb 2007 06:07:11 +0200	[thread overview]
Message-ID: <45CD44EF.6080807@domain.hid> (raw)
In-Reply-To: <45CCCD10.9000008@domain.hid>

Hi!

I added some logging to mutex log operation and serial port operations 
(executed in secondary mode):

--- skipped ---
#ifdef _DEBUG_
struct log_mutex_opers
{
     RT_TASK_INFO task_info_before;
     RT_TASK_INFO task_info_after;
     RT_MUTEX_INFO mutex_info;
     unsigned char oper;
     RTIME oper_in;
     RTIME oper_out;
     int ser_trans_count;
     RTIME ser_trans_in[128];
     RTIME ser_trans_out[128];
};
#endif /* _DEBUG_ */
--- skipped ---
#ifdef _DEBUG_
#define lock_history_lenght 1000
     struct log_mutex_opers logs[2*lock_history_lenght];
     unsigned long logs_c1;
     unsigned long logs_c2;
#endif /* _DEBUG_ */
--- skipped ---
#define SER_TRANS_LOG(C, T1, T2)                                \
{                                                               \
     int __i = C->logs[0].ser_trans_count;                       \
     C->logs[0].ser_trans_in[__i] = T1;                          \
     C->logs[0].ser_trans_out[__i] = T2;                         \
     C->logs[0].ser_trans_count++;                               \
}
#define _SAVE_STATE_COLLECTION(C, T, O, S)                      \
{                                                               \
     RTIME __t2 = rt_timer_tsc();                                \
     int __i;                                                    \
     for(__i = (2*lock_history_lenght - 1); __i > 0; __i--)      \
         C->logs[__i] = C->logs[__i - 1];                        \
     memset(&C->logs[0], 0, sizeof(struct log_mutex_opers));     \
     rt_task_inquire(NULL, &C->logs[0].task_info_after);         \
     rt_mutex_inquire(&C->lock, &C->logs[0].mutex_info);         \
     C->logs[0].oper = O;                                        \
     C->logs[0].oper_out = __t2;                                 \
     C->logs[0].oper_in = T;                                     \
     C->logs[0].task_info_before = S;                            \
}

#define _LOCK_COLLECTION(C, I)                                  \
{                                                               \
     RTIME __t1 = rt_timer_tsc();                                \
     RT_TASK_INFO __s;                                           \
     rt_task_inquire(NULL, &__s);                                \
     RT_MUTEX_INFO __lock_state;                                 \
     rt_mutex_inquire(&C->lock, &__lock_state);                  \
     rt_mutex_lock(&C->lock ,TM_INFINITE );                      \
     _SAVE_STATE_COLLECTION(C, __t1, 'L', __s);                  \
     I++;                                                        \
};

#define LOCK_COLLECTION_NR(C)                                   \
     _LOCK_COLLECTION(C, C->logs_c1)

#define LOCK_COLLECTION(C, R)                                   \
     _LOCK_COLLECTION(C, C->logs_c2)

#define UNLOCK_COLLECTION(C)                                    \
{                                                               \
     RT_TASK_INFO __s;                                           \
     rt_task_inquire(NULL, &__s);                                \
     _SAVE_STATE_COLLECTION(C, 0, 'U', __s);                     \
     rt_mutex_unlock(&C->lock);                                  \
};
--- skipped ---

After deadlock reached, array has entries ( i listed here last 6 entries 
- one pair is lock/unlock registration):

------------------------------------------------------------------

{{task_info_before = {bprio = 80, cprio = 80, status = 3146624, relpoint 
= 0,
       name = 
"vdcp[0030]m\000\226\002\000\000\231?\023??8N?\202\002\000\000H\037H?"}, 
task_info_after = {bprio = 80,
       cprio = 80, status = 3146624, relpoint = 0,
       name = 
"vdcp[0030]m\000\226\002\000\000\231?\023??8N?\202\002\000\000H\037H?"}, 
mutex_info = {lockcnt = 1,
       nwaiters = 1, name = 
"coll_VDCP_1\000\231?\023??8N?\202\002\000\000H\037H?4?\020?"}, oper = 
85 'U', oper_in = 0,
     oper_out = 5397829215210, ser_trans_count = 0, ser_trans_in = {0 
<repeats 128 times>}, ser_trans_out = {
       0 <repeats 128 times>}},

{task_info_before = {bprio = 80, cprio = 80, status = 3146112, relpoint = 0,
       name = 
"vdcp[0030]m\000\226\002\000\000\231?\023??8N?\202\002\000\000H\037H?"}, 
task_info_after = {bprio = 80,
       cprio = 80, status = 3146112, relpoint = 0,
       name = 
"vdcp[0030]m\000\226\002\000\000\231?\023??8N?\202\002\000\000H\037H?"}, 
mutex_info = {lockcnt = 1,
       nwaiters = 0, name = 
"coll_VDCP_1\000\231?\023??8N?\202\002\000\000H\037H?4?\020?"}, oper = 
76 'L',
     oper_in = 5397792126988, oper_out = 5397792191552, ser_trans_count 
= 1, ser_trans_in = {5397810469917,
       0 <repeats 127 times>}, ser_trans_out = {5397828986260, 0 
<repeats 127 times>}},



{task_info_before = {bprio = 50,
       cprio = 50, status = 3146112, relpoint = 0, name = 
"bus_monitor_proc[0]\000?8N?\202\002\000\000H_??"},
     task_info_after = {bprio = 50, cprio = 50, status = 3146112, 
relpoint = 0,
       name = "bus_monitor_proc[0]\000?8N?\202\002\000\000H_??"}, 
mutex_info = {lockcnt = 1, nwaiters = 0,
       name = 
"coll_VDCP_1\000\231?\023??8N?\202\002\000\000H_??4?\020?"}, oper = 85 
'U', oper_in = 0,
     oper_out = 5397750468006, ser_trans_count = 1, ser_trans_in = 
{5397718529990, 0 <repeats 127 times>}, ser_trans_out = {
       5397770396236, 0 <repeats 127 times>}},

{task_info_before = {bprio = 50, cprio = 50, status = 3146112, relpoint = 0,
       name = "bus_monitor_proc[0]\000?8N?\202\002\000\000H_??"}, 
task_info_after = {bprio = 50, cprio = 50,
       status = 3146112, relpoint = 0, name = 
"bus_monitor_proc[0]\000?8N?\202\002\000\000H_??"}, mutex_info = 
{lockcnt = 1,
       nwaiters = 0, name = 
"coll_VDCP_1\000\231?\023??8N?\202\002\000\000H_??4?\020?"}, oper = 76 'L',
     oper_in = 5397732302828, oper_out = 5397732320388, ser_trans_count 
= 0, ser_trans_in = {0 <repeats 128 times>},
     ser_trans_out = {0 <repeats 128 times>}},




{task_info_before = {bprio = 80, cprio = 80, status = 3146112, relpoint = 0,
       name = 
"vdcp[0030]m\000\226\002\000\000\231?\023??8N?\202\002\000\000H\037H?"}, 
task_info_after = {bprio = 80,
       cprio = 80, status = 3146112, relpoint = 0,
       name = 
"vdcp[0030]m\000\226\002\000\000\231?\023??8N?\202\002\000\000H\037H?"}, 
mutex_info = {lockcnt = 1,
       nwaiters = 0, name = 
"coll_VDCP_1\000\231?\023??8N?\202\002\000\000H\037H?4?\020?"}, oper = 
85 'U', oper_in = 0,
     oper_out = 5397682575612, ser_trans_count = 1, ser_trans_in = 
{5397701107940, 0 <repeats 127 times>}, ser_trans_out = {
       5397718501300, 0 <repeats 127 times>}},

{task_info_before = {bprio = 80, cprio = 80, status = 3146112, relpoint = 0,
       name = 
"vdcp[0030]m\000\226\002\000\000\231?\023??8N?\202\002\000\000H\037H?"}, 
task_info_after = {bprio = 80,
       cprio = 80, status = 3146112, relpoint = 0,
       name = 
"vdcp[0030]m\000\226\002\000\000\231?\023??8N?\202\002\000\000H\037H?"}, 
mutex_info = {lockcnt = 1,
       nwaiters = 0, name = 
"coll_VDCP_1\000\231?\023??8N?\202\002\000\000H\037H?4?\020?"}, oper = 
76 'L',
     oper_in = 5397664238700, oper_out = 5397664304073, ser_trans_count 
= 0, ser_trans_in = {0 <repeats 128 times>},
     ser_trans_out = {0 <repeats 128 times>}},

--- skipped ---

------------------------------------------------------------------

I tried to summarize this info and build time sorted table of actions 
(task B - "bus_monitor_proc[0]", task V - "vdcp[0030]m"):

V	5397829215210	rt_mutex_unlock:ENTER
V	5397828986260	serial_transact:EXIT
V	5397810469917	serial_transact:ENTER
V	5397792191552	rt_mutex_lock:EXIT
V	5397792126988	rt_mutex_lock:ENTER
V	5397770396236	serial_transact:EXIT
B	5397750468006	rt_mutex_unlock:ENTER
B	5397732320388	rt_mutex_lock:EXIT
B	5397732302828	rt_mutex_lock:ENTER
V	5397718529990	serial_transact:ENTER
V	5397718501300	serial_transact:EXIT
V	5397701107940	serial_transact:ENTER
V	5397682575612	rt_mutex_unlock:ENTER
V	5397664304073	rt_mutex_lock:EXIT
V	5397664238700	rt_mutex_lock:ENTER
V	5397618710764	rt_mutex_unlock:ENTER
V	5397600363677	rt_mutex_lock:EXIT
V	5397600295612	rt_mutex_lock:ENTER

As i mentioned early task B was executed during serial operation in task 
V, and may be it could cause switching status of task V from 3146112 
(0x00300180) to 3146624 (0x00300380) - rised bit 0x00000200 (XNRELAX 
0x00000200 Relaxed shadow thread (blocking bit) )

I am not specialist in Xenomai architecture, but it's not looks like 
stack corruption in my program.

I rather going to rewrite some code part to use rtserX instead of /dev/ttyXX


________________________________________
Maksym Veremeyenko



  parent reply	other threads:[~2007-02-10  4:07 UTC|newest]

Thread overview: 10+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2007-02-09 19:35 [Xenomai-help] Strange deadlock Maksym Veremeyenko
2007-02-09 20:54 ` Philippe Gerum
2007-02-09 21:39   ` Maksym Veremeyenko
2007-02-09 21:14 ` Dmitry Adamushko
2007-02-09 22:10   ` Maksym Veremeyenko
2007-02-09 23:53     ` Dmitry Adamushko
2007-02-10  4:07 ` Maksym Veremeyenko [this message]
2007-02-10 10:34   ` Jan Kiszka
2007-02-11 18:28     ` Maksym Veremeyenko
2007-02-11 19:05       ` Philippe Gerum

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=45CD44EF.6080807@domain.hid \
    --to=verem@domain.hid \
    --cc=Xenomai-help@domain.hid \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.