Skip to content

Conversation

@dwrobel
Copy link
Contributor

@dwrobel dwrobel commented Jul 28, 2020

Signed-off-by: Damian Wrobel dwrobel@ertelnet.rybnik.pl

Signed-off-by: Damian Wrobel <dwrobel@ertelnet.rybnik.pl>
@andypugh
Copy link
Collaborator

Can you elaborate slightly on what led you to conclude that this needed to change?

@dwrobel
Copy link
Contributor Author

dwrobel commented Jul 28, 2020

Can you elaborate slightly on what led you to conclude that this needed to change?

I'm working on a rootless linuxcnc and was doing some changes in that area. So, I was trying to understand what is the purpose of this lock and if I'm not mistaken, it looks it's not used at all. If that's correct then IMHO it's better to remove it.

@andypugh andypugh requested a review from jepler July 28, 2020 21:13
@jepler
Copy link
Contributor

jepler commented Jul 29, 2020

The intent of the lock is to ensure that non-realtime uspace gives a thread scheduling promise at least as strong as rate monotonic scheduling. From the message of the commit that added it in 2014, cbbd8e5:

For SCHED_FIFO, using distinct priorities gives rate monotonic
scheduling.  For SCHED_OTHER (running without root privs), locks give
the same no-slow-interrupts-fast guarantee as pth did (a slightly
different guarantee than RMS, because it also prevents fast interrupting
slow).

Since your proposed change has to remove sites where the mutex was taken and released, I do not understand why you state it appears to be unused.

The test called threads.0 is inteded to fail when the absence of rate monotonic scheduling is detected.

Reportedly, the machinekit fork of LinuxCNC has given up the rate-monotonic guarantee. Before this can be done in LinuxCNC, the small number of components that create multiple realtime threads -- e.g., software stepgen and encoder, maybe that's about it? -- need to be checked for whether the way they communicate from "fast" to "slow" thread still works when rate monotonic scheduling is not guaranteed.

@dwrobel
Copy link
Contributor Author

dwrobel commented Jul 29, 2020

I don't see how this could work

1 wait() {
2    unlock()
3
4    lock()
5}

as neither for a single thread or two threads invoking wait() method there will be no contention which would trigger the rescheduling. On the other hand, if one thread got to the point (3) and another is at (2) you will simply try to unlock unlocked mutex which will generate undefined behavior (see: Unlock When Not Owner column).

@jepler
Copy link
Contributor

jepler commented Aug 1, 2020

The locked section is from Posix::wrapper to Posix::wait. Then Posix::wait briefly unlocks, allowing a different RT task to take over during its sleep. Then it locks again, making the next locked section from this wait to the next wait.

If you have information indicating there is a bug here, please provide it so we can find a solution together.

@jepler jepler closed this Aug 1, 2020
@dwrobel
Copy link
Contributor Author

dwrobel commented Aug 1, 2020

If you have information indicating there is a bug here, please provide it

I provided it in a previous post:

if one thread got to the point (3) and another is at (2) you will simply try to unlock unlocked mutex which will generate undefined behavior (see: Unlock When Not Owner column).

I also provided a link to the pthread_mutex_lock() specification where you can read more about the undefined behavior.

@jepler
Copy link
Contributor

jepler commented Aug 1, 2020

With respect, I do not think you have understood how the code works. However, it's also possible I'm overlooking something.

More typically, you'll see code that looks like this:

void function_with_critical_section() {
    pthread_mutex_lock(&lock);
    // critical section here
    pthread_mutex_unlock(&lock);
}

the lock and unlock appear in the same function, and the lock precedes the unlock. To see them in the opposite order looks pretty weird. Here's what the code is doing, albeit with more levels of function calls intervening:

void function_with_critical_section_loop() {
   pthread_mutex_lock(&lock); // this is in Posix::wrapper (1)
   while(true) { // this while-loop is in hal_lib.c:thread_task
        // critical section here, the actual HAL functions linked to this thread

        // the unlock-then-lock idiom is in Posix::wait
        pthread_mutex_unlock(&lock); // reached subsequent to either lock(1) or lock(2)
        // sleep and check for cancel without holding lock
        pthread_mutex_lock(&lock); (2)
   }
}

So the unlock is always preceded by a lock. The only exit is from "check for cancel", which occurs while the lock is not held. Whether the unlock is reached on the first iteration of the while loop or a subsequent iteration, it corresponds with a temporally previous lock from the same thread.

However, the fact that this is spread across multiple functions in multiple source modules may have made the overall structure nonobvious.

By ensuring that only one HAL realtime thread is never interrupted by another except during the thread's "wait", we provide for the simulator a stronger guarantee than we provide for RT, which is the rate monotonic guarantee. However, this stronger guarantee (and the structure providing it) should not be depended on; it provided what seemed to me a convenient implementation.

@rene-dev
Copy link
Member

rene-dev commented Aug 2, 2020

is this related to #692 ?

@jepler
Copy link
Contributor

jepler commented Aug 2, 2020

Not exactly, this is about non rt but that is about rt.

@dwrobel
Copy link
Contributor Author

dwrobel commented Aug 3, 2020

Let's reuse annotations from my example:

1 wait() {
2    unlock()
3
4    lock()
5}

in your code:

  void function_with_critical_section_loop() {
     pthread_mutex_lock(&lock); // this is in Posix::wrapper 
     while(true) { // this while-loop is in hal_lib.c:thread_task
          // critical section here, the actual HAL functions linked to this thread
  
1       // the unlock-then-lock idiom is in Posix::wait
2       pthread_mutex_unlock(&lock);
3       // sleep and check for cancel without holding lock
4       pthread_mutex_lock(&lock);
5 }
}

and then quote once more the following text from:

if one thread got to the point (3) and another is at (2) you will simply try to unlock unlocked mutex which will generate undefined behavior (see: Unlock When Not Owner column).

Now if you can fit all of them in one screen, it should be easier to notice that the code is wrong in 2 as you cannot allow two threads to execute pthread_mutex_unlock(&lock) on the same lock - that's either an error or undefined behavior.

You might try to solve that issue by adding pthread_cond_t plus some counter variable and synchronize the code using pthread_cond_wait(), pthread_cond_signal() but that will not help the code to work better in that particular case.

It would interested to hear from you what's your observation if you use the latency-test as non-root. My observation is that the
Last interval (ns) for Base thread (25us) varies between 340-400 instead of being close to 25000. For the record I'm using the kernel: Linux dell 5.7.7-100.fc31.x86_64 #1 SMP Wed Jul 1 20:37:05 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux.

@jepler
Copy link
Contributor

jepler commented Aug 3, 2020

[I] would interested to hear from you what's your observation if you use the latency-test as non-root. My observation is that the
Last interval (ns) for Base thread (25us) varies between 340-400 instead of being close to 25000

Yes that's what the UI shows, but it's NOT an accurate reflection of the average. It's a form of the train arrival paradox https://math.stackexchange.com/questions/1446874/train-arrival-paradox

image

Here we see the "last base thread time" (hal signal name lat.bt) in halscope, so each successive value of it is captured. You can see that it is multimodal with many instances near 0 and many instances near 75000 but some going higher.

Basically, we're asking for small sleeps that at least non-RT kernels with SCHED_OTHER scheduling will not furnish. So we sleep a lot longer than requested if we DO sleep, and skip sleeping at all when we know the next deadline has already passed:

    clock_gettime(RTAPI_CLOCK, &now);
    if(rtapi_timespec_less(task->nextstart, now))
    {
        if(policy == SCHED_FIFO)                                    // non-RT is hitting this case 2/3 of the time on my system
            unexpected_realtime_delay(task);
    }
    else
    {
        int res = rtapi_clock_nanosleep(RTAPI_CLOCK, TIMER_ABSTIME, &task->nextstart, nullptr, &now);
        if(res < 0) perror("clock_nanosleep");
    }

Now, it happens almost everytime that when we entered the else{} branch and DID sleep we will NOT sleep the next time, that causes the high value like 75000 to almost always be replaced by a low time like 250 when we hit the other path on the next run through.

That doesn't mean that you can or should conclude that the average time is wrong. And, anyway, we don't keep any RT guarantees.

You can also see that with e.g., latency-test 5ms 250us of course we are still not meeting realtime deadlines but at least the base thread last interval is often close to the nominal requested value, because apparently 250us is within the range of a small sleep on my system. (this is actually on a -rt kernel but I have not "sudo make setuid" and linuxcnc / hal report "Note: Using POSIX non-realtime")

image

As for the question of correct pthread mutex handling, I would like to understand whether

  1. You believe that my simplified code still shows the problem you are calling out earlier in this thread, so discussing it further is useful; or
  2. You believe that my simplified code is "not wrong" because it lost some detail of the problem you are trying to explain, so discussing it further is not useful

@dwrobel
Copy link
Contributor Author

dwrobel commented Aug 4, 2020

You believe that my simplified code still shows the problem you are calling out earlier in this thread, so discussing it further is useful;

IMHO the simplified code perfectly depicts either error of undefined behaviour as per posix specification.

As you closed this PR, I submitted #918 where you can see how this PR fits into a bigger picture. I would appreciate to get your feedback.

[I] would interested to hear from you what's your observation if you use the latency-test as non-root. My observation is that the Last interval (ns) for Base thread (25us) varies between 340-400 instead of being close to 25000

Yes that's what the UI shows, but it's NOT an accurate reflection of the average.

As as side effect #918 should also helps latency-test to work more reliably on non-rt kernels (on modern hardware latency-test 1000000 25000 works quite stable, on the very old hardware latency-test 1000000 50000 was enough to get quite stable result).

@jepler
Copy link
Contributor

jepler commented Aug 4, 2020

CBMC is a very useful program that can in certain circumstances prove programs are "correct". Among other things, it can check that the conditions of pthread mutexes are respected in all possible circumstances.

I have modified the already simplified version of the mutex handling into a program suitable to feed to CBMC.

#include <pthread.h>
#include <stdio.h>
#include <stdlib.h>

pthread_mutex_t mut;

void fatal(const char *why) {
    abort();
}

int nondet_int();

void *task(void *unused) {
    pthread_mutex_lock(&mut);
    // The CBMC can't prove anything about infinite loops.  However, anything
    // interesting will occur within a fixed number of loops.
    for(int i=0; i<2; i++) {
        pthread_mutex_unlock(&mut);
#ifdef ERROR
        // By defining -DERROR, cbmc will print the result
        // VERIFICATION FAILED since there is an unlock of a not-locked mutex.
        // However, this second non-deterministic unlock does not exist in
        // LinuxCNC.  This block is purely to demonstrate that CBMC/CPROVER
        // work and would detect errors of this kind.
        int unlock_twice = nondet_int();
        if(unlock_twice) {
            pthread_mutex_unlock(&mut);
        }
#endif
        pthread_mutex_lock(&mut);
    }

    // compared to LinuxCNC, which exits from the middle of the loop
    // with the lock not held, this example exits from the end of the loop
    // so an extra unlock is required.
    pthread_mutex_unlock(&mut);
}


int main() {
    pthread_mutexattr_t attr;

    pthread_mutexattr_init(&attr);
    pthread_mutexattr_settype(&attr, PTHREAD_MUTEX_ERRORCHECK);
    pthread_mutex_init(&mut, &attr);

    pthread_t p1, p2;

    if(pthread_create(&p1, NULL, task, NULL)) {
        fatal("pthread_create p1");
    }

    if(pthread_create(&p2, NULL, task, NULL)) {
        fatal("pthread_create p1");
    }
    
    pthread_join(p1, NULL);
    pthread_join(p2, NULL);
}

According to cprover, this simplified version of what LinuxCNC does passes verification:

$ cbmc threaderr.c 
CBMC version 5.10 (cbmc-5.10) 64-bit x86_64 linux
Parsing threaderr.c
Converting
Type-checking threaderr
Generating GOTO Program
Adding CPROVER library (x86_64)
Removal of function pointers and virtual functions
file <builtin-library-pthread_create> line 39 function pthread_create: replacing function pointer by 1 possible targets
Generic Property Instrumentation
Running with 8 object bits, 56 offset bits (default)
Starting Bounded Model Checking
**** WARNING: no body for function pthread_mutexattr_init
Unwinding loop task.0 iteration 1 file threaderr.c line 17 function task thread 1
Unwinding loop task.0 iteration 2 file threaderr.c line 17 function task thread 1
Unwinding loop task.0 iteration 1 file threaderr.c line 17 function task thread 2
Unwinding loop task.0 iteration 2 file threaderr.c line 17 function task thread 2
Adding SC constraints
Shared __CPROVER_threads_exited: 4R/3W
Shared __CPROVER_next_thread_id: 3R/3W
Shared mut: 12R/14W
Shared main::1::p1!0@1: 2R/2W
Shared main::1::p2!0@1: 2R/2W
size of program expression: 2304 steps
no slicing due to threads
Generated 6 VCC(s), 6 remaining after simplification
Passing problem to propositional reduction
converting SSA
Running propositional reduction
Post-processing
Solving with MiniSAT 2.2.1 with simplifier
50369 variables, 222407 clauses
SAT checker: instance is UNSATISFIABLE
Runtime decision procedure: 1.71704s

** Results:
[pthread_mutex_unlock.assertion.1] must hold lock upon unlock: SUCCESS

** 0 of 1 failed (1 iteration)
VERIFICATION SUCCESSFUL

And in particular, [pthread_mutex_unlock.assertion.1] must hold lock upon unlock: SUCCESS

In case you would like to see how it detects a failure of the sort you are talking about, you can instead invoke it as $ cbmc threaderr.c -DERROR in which case some incorrect code is enabled. Its output will state

[pthread_mutex_unlock.assertion.1] must hold lock upon unlock: FAILURE

You are also free to take a look at #916 in which the error-checking mode of mutexes is enabled, so that if my analysis is wrong a runtime error and abort will promptly result.

@dwrobel
Copy link
Contributor Author

dwrobel commented Aug 6, 2020

In case you would like to see how it detects a failure of the sort you are talking about, you can instead invoke it as $ cbmc threaderr.c -DERROR in which case some incorrect code is enabled. Its output will state

[pthread_mutex_unlock.assertion.1] must hold lock upon unlock: FAILURE

I'm glad you can finally confirm the issue with the code.

You are also free to take a look at #916 in which the error-checking mode of mutexes is enabled,

Yeah, that seems to be seeing is believing approach, however, the real art is to believe (based on the specification only) not seeing.

@jepler
Copy link
Contributor

jepler commented Aug 6, 2020

You misunderstand -- I believe CBMC proves the code in LinuxCNC is correct. "-DERROR" deliberately introduces incorrect code that is not reflective of LinuxCNC.

        // By defining -DERROR, cbmc will print the result
        // VERIFICATION FAILED since there is an unlock of a not-locked mutex.
        // However, this second non-deterministic unlock does not exist in
        // LinuxCNC.  This block is purely to demonstrate that CBMC/CPROVER
        // work and would detect errors of this kind.

@dwrobel
Copy link
Contributor Author

dwrobel commented Aug 6, 2020

I believe CBMC proves the code in LinuxCNC is correct.

This seems to be far fetched. In order to make such a statement you would first have to prove two following statements:
a) CBMC can detect all errors and undefined behavior defined by the Posix API w.r.t to locks.
b) while running CBMS you need to be sure that it triggers all combination of timings.

Please try to answer to the following questions:

  1. do you agree that according to the Posix specification an attempt to unlock unlocking lock is either error or undefined behavior?
  2. do you agree that if two threads will try to execute the following line: https://github.com/LinuxCNC/linuxcnc/pull/912/files#diff-1e0916462e2abd03736e702b73ce6c11L1090 one of them will try to unlock unlocked lock?

@jepler
Copy link
Contributor

jepler commented Aug 6, 2020

I do not "prove" that CBMC can detect all errors. However, CBMC's design is such that it SHOULD exhaustively prove that the specific kind of error we are discussing can never occur in the toy sample program. If it did not, then it would be an interesting example to the CBMC maintainers. CBMC does not "run" the software in a traditional way, rather it creates a model of the program and then proves that properties (such as pthread_mutex_unlock.assertion.1, that a lock is held when it is unlocked) are invariants of the program. In that way, it is exhaustive and is not dependent on timing properties.

According to the CBMC authors on a different aspect of pthread correctness proving,

Our approach is sound (i.e., misses no deadlocks) for programs that have defined behaviour[sic] according to the C standard, and precise enough to prove deadlock-freedom for a large number of programs.

(I did not find a specific citation about the assertion known as pthread_mutex_unlock.assertion.1)

CBMC is also cited a couple of times in Is Parallel Programming Hard, And, If So, What Can You Do About It? so it seems to be taken seriously as a tool for this purpose by those who are expert in the field.

As to your specific questions:

  1. Yes
  2. I am satisfied that this situation cannot occur

I do not believe it is productive to continue this discussion without additional information or a new perspective. I have provided the best information I can and honestly I remain bewildered that we cannot agree about this. I am going to seek someone else without a vested interest for their views on this matter, and I suggest you do the same; it's clear that the two of us are not going to come to an understanding through more discussion.

@dwrobel
Copy link
Contributor Author

dwrobel commented Aug 7, 2020

As to your specific questions:

  1. Yes
  2. I am satisfied that this situation cannot occur

Unfortunately, the 2. is not an answer but rather a jump to conclusion.

You would be surprised how often this occurs in reality. Here is the session recorded from gdb.

In order to reproduce it, please run in one console:

$ latency-test

while on the other console attach gdb to rtapi_app process and execute the following commands (the below session contains some additional comments with the prefix #dw:):

$ gdb -p  $(pidof rtapi_app)
GNU gdb (GDB) Fedora 8.3.50.20190824-30.fc31
Copyright (C) 2019 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 1831732
[New LWP 1831733]
[New LWP 1831734]
[New LWP 1831735]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
0x00007f3f7ee439af in __libc_accept (fd=3, addr=..., len=0x7ffeb6cda4ec) at ../sysdeps/unix/sysv/linux/accept.c:26
26	  return SYSCALL_CANCEL (accept, fd, addr.__sockaddr__, len);
(gdb) info thr #dw: dump the list of threads
  Id   Target Id                                       Frame 
* 1    Thread 0x7f3f7e709cc0 (LWP 1831732) "rtapi_app" 0x00007f3f7ee439af in __libc_accept (fd=3, addr=..., len=0x7ffeb6cda4ec) at ../sysdeps/unix/sysv/linux/accept.c:26
  2    Thread 0x7f3f7e706700 (LWP 1831733) "rtapi_app" 0x00007f3f7ed2f7d1 in __clock_nanosleep (clock_id=1, flags=0, req=0x7f3f7e705dd0, rem=0x0) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:40
  3    Thread 0x7f3f7deb0700 (LWP 1831734) "rtapi_app" 0x00007f3f7ed2f7d1 in __clock_nanosleep (clock_id=1, flags=1, req=0x1a81d08, rem=0x0) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:40
  4    Thread 0x7f3f7ddaf700 (LWP 1831735) "rtapi_app" 0x00007f3f7ed2f7d1 in __clock_nanosleep (clock_id=1, flags=1, req=0x1a81ed8, rem=0x0) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:40
(gdb) thr 3 # switch to thread nr.3
[Switching to thread 3 (Thread 0x7f3f7deb0700 (LWP 1831734))]
#0  0x00007f3f7ed2f7d1 in __clock_nanosleep (clock_id=1, flags=1, req=0x1a81d08, rem=0x0) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:40
40	  int r = INTERNAL_SYSCALL_CANCEL (clock_nanosleep, err, clock_id, flags,
(gdb) b uspace_rtapi_app.cc:1091 #dw: setup a brakpoint after the thread unlocked a lock at https://github.com/LinuxCNC/linuxcnc/pull/912/files#diff-1e0916462e2abd03736e702b73ce6c11L1090
Breakpoint 1 at 0x41e16e: file rtapi/uspace_rtapi_app.cc, line 1091.
(gdb) c # continue the execution of the program
Continuing.

Thread 3 "rtapi_app" hit Breakpoint 1, (anonymous namespace)::Posix::wait (this=0x1a811c0) at rtapi/uspace_rtapi_app.cc:1091
1091	    pthread_testcancel();
(gdb) t a a bt #dw: dump all callstacks (as you clearly see both of the threads (3) and (4) unlocked the lock

Thread 4 (Thread 0x7f3f7ddaf700 (LWP 1831735)):
#0  (anonymous namespace)::Posix::wait (this=0x1a811c0) at rtapi/uspace_rtapi_app.cc:1091
#1  0x000000000041e54a in rtapi_wait () at rtapi/uspace_rtapi_app.cc:1208
#2  0x00007f3f7f274700 in thread_task (arg=0x7f3f7df05d00) at hal/hal_lib.c:2871
#3  0x000000000041e00b in (anonymous namespace)::Posix::wrapper (arg=0x1a81eb0) at rtapi/uspace_rtapi_app.cc:1053
#4  0x00007f3f7ee394e2 in start_thread (arg=<optimized out>) at pthread_create.c:479
#5  0x00007f3f7ed686a3 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 3 (Thread 0x7f3f7deb0700 (LWP 1831734)):
#0  (anonymous namespace)::Posix::wait (this=0x1a811c0) at rtapi/uspace_rtapi_app.cc:1091
#1  0x000000000041e54a in rtapi_wait () at rtapi/uspace_rtapi_app.cc:1208
#2  0x00007f3f7f274700 in thread_task (arg=0x7f3f7df05ea0) at hal/hal_lib.c:2871
#3  0x000000000041e00b in (anonymous namespace)::Posix::wrapper (arg=0x1a81ce0) at rtapi/uspace_rtapi_app.cc:1053
#4  0x00007f3f7ee394e2 in start_thread (arg=<optimized out>) at pthread_create.c:479
#5  0x00007f3f7ed686a3 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 2 (Thread 0x7f3f7e706700 (LWP 1831733)):
#0  0x00007f3f7ed2f7d1 in __clock_nanosleep (clock_id=1, flags=0, req=0x7f3f7e705dd0, rem=0x0) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:40
#1  0x000000000041a8ae in rtapi_clock_nanosleep (clock_id=1, flags=0, prequest=0x7f3f7e705dd0, remain=0x0, pnow=0x0) at ./rtapi/uspace_common.h:400
#2  0x000000000041a9c6 in (anonymous namespace)::queue_function (arg=0x0) at rtapi/uspace_rtapi_app.cc:114
#3  0x00007f3f7ee394e2 in start_thread (arg=<optimized out>) at pthread_create.c:479
#4  0x00007f3f7ed686a3 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 1 (Thread 0x7f3f7e709cc0 (LWP 1831732)):
#0  0x00007f3f7ee439af in __libc_accept (fd=3, addr=..., len=0x7ffeb6cda4ec) at ../sysdeps/unix/sysv/linux/accept.c:26
#1  0x000000000041c13e in callback (fd=3) at rtapi/uspace_rtapi_app.cc:413
#2  0x000000000041e5ee in (anonymous namespace)::Posix::run_threads (this=0x1a811c0, fd=3, callback=0x41c0e9 <callback(int)>) at rtapi/uspace_rtapi_app.cc:1226
#3  0x000000000041e62d in sim_rtapi_run_threads (fd=3, callback=0x41c0e9 <callback(int)>) at rtapi/uspace_rtapi_app.cc:1231
#4  0x000000000041c4ca in master (fd=3, args=std::vector of length 6, capacity 6 = {...}) at rtapi/uspace_rtapi_app.cc:455
#5  0x000000000041cb08 in main (argc=7, argv=0x7ffeb6cda8f8) at rtapi/uspace_rtapi_app.cc:542
(gdb) thr 4 #dw: analyse the first thread
[Switching to thread 4 (Thread 0x7f3f7ddaf700 (LWP 1831735))]
#0  (anonymous namespace)::Posix::wait (this=0x1a811c0) at rtapi/uspace_rtapi_app.cc:1091
1091	    pthread_testcancel();
(gdb) l #dw: verify that line 1091 is actually the line after the thread unlocked the lock
1086	}
1087	
1088	void Posix::wait() {
1089	    if(do_thread_lock)
1090	        pthread_mutex_unlock(&thread_lock);
1091	    pthread_testcancel();
1092	    struct rtapi_task *task = reinterpret_cast<rtapi_task*>(pthread_getspecific(key));
1093	    rtapi_timespec_advance(task->nextstart, task->nextstart, task->period + task->pll_correction);
1094	    struct timespec now;
1095	    clock_gettime(RTAPI_CLOCK, &now);
(gdb) p do_thread_lock #dw: this is to prove that previously the thread executed line 1090
$1 = true
(gdb) p &thread_lock #dw: dump the address of the lock
$2 = (pthread_mutex_t *) 0x1a811e0
(gdb) thr 3 #dw: do the same analysis for the second thread
[Switching to thread 3 (Thread 0x7f3f7deb0700 (LWP 1831734))]
#0  (anonymous namespace)::Posix::wait (this=0x1a811c0) at rtapi/uspace_rtapi_app.cc:1091
1091	    pthread_testcancel();
(gdb) l #dw: verify that line 1091 is actually the line after the thread unlocked the lock
1086	}
1087	
1088	void Posix::wait() {
1089	    if(do_thread_lock)
1090	        pthread_mutex_unlock(&thread_lock);
1091	    pthread_testcancel();
1092	    struct rtapi_task *task = reinterpret_cast<rtapi_task*>(pthread_getspecific(key));
1093	    rtapi_timespec_advance(task->nextstart, task->nextstart, task->period + task->pll_correction);
1094	    struct timespec now;
1095	    clock_gettime(RTAPI_CLOCK, &now);
(gdb) p do_thread_lock #dw: this is to prove that previously the thread executed line 1090
$3 = true
(gdb) p &thread_lock #dw: dump the address of the lock - as you can see both threads unlocked the same lock
$4 = (pthread_mutex_t *) 0x1a811e0
(gdb) 

I do not believe it is productive to continue this discussion without additional information or a new perspective.

I'm hopping this should finally convince you and I'm partially surprised that it was so difficult to understand why this code is wrong.

@jepler
Copy link
Contributor

jepler commented Aug 7, 2020

It is no surprise that multiple threads can be within the line range 1091..1105 (in the region from the unlock to the lock) because this is the range of lines NOT protected by the lock. For instance, say your two threads had a period of "1 day" and "1 week" -- most of the time, your debugger would show that they were both in the sleep call. This could happen with the following sequence of events:

  • Fast thread takes lock & does 1 second of work
  • Fast thread unlocks
  • Fast thread begins sleeping for 1 day
  • Slow thread takes lock & does 1 minute of work
  • Slow thread unlocks
  • Slow thread begins sleeping for 1 week

Even with 1ms & 25us threads in latency-test, most of the time will be spent in testcancel and sleep, because the "work" is on the order of 300ns.

You may want to reflect on your dismissal of #916 (that the addition of error-checked mutexes proves nothing, it could just be that the situation is infrequent) in light of your new claim that the error condition occurs readily under the debugger. Can all these be true?


The important thing we can say is: it is a precondition of Posix::wait that the lock be held by this thread. If this precondition does not hold, then we will unlock a not-locked lock.

Which paths arrive at unlock? Returning to the simplified program, which you considered to be equivalent to what LinuxCNC was doing, let's look at it again:

     1	void function_with_critical_section_loop() {
     2	   pthread_mutex_lock(&lock); // this is in Posix::wrapper (A)
     3	   while(true) { // this while-loop is in hal_lib.c:thread_task
     4	        // critical section here, the actual HAL functions linked to this thread
     5	
     6	        // the unlock-then-lock idiom is in Posix::wait
     7	        pthread_mutex_unlock(&lock); // reached subsequent to either lock(A) or lock(B)
     8	        // sleep and check for cancel without holding lock
     9	        pthread_mutex_lock(&lock); (B)
    10	   }
    11	}

Here, the precondition changes to "the lock is held at the top of the while-loop". There are two paths to the top of the while loop, from line 2 or from line 9. Both paths take the lock. Therefore, the precondition holds.

Let's look at it another way, hopefully as a series of transformations we can agree preserve the "lock is held by this thread when unlock is called" invariant.

Basic: function executes linearly, critical section, no loop

f1() {
    lock();
    unlock();
}

Critical section is repeated in a loop until canceled

Note the sequence of calls is: lock / unlock / testcancel

f2() { 
    while(1) {
        lock();
        unlock();
        testcancel();
    }
}

Roll body of while loop

Note that the sequence is still lock / unlock / testcancel.
This is function_with_critical_section_loop earlier in our discussion.

f3() { 
    lock();
    while(1) {
        unlock();
        testcancel();
        lock();
    }
}

@dwrobel
Copy link
Contributor Author

dwrobel commented Aug 7, 2020

2 I am satisfied that this situation cannot occur

It proves that you were wrong saying that it cannot occur.

You may want to reflect on your dismissal of #916 (that the addition of error-checked mutexes proves nothing,

It could be equally true that, error-checking in mutexes simply cannot detect this situation or it's not properly implemented, if at all. That's why it's so important to use the API according to the specification and not rely on any extra tool or error checking.

it could just be that the situation is infrequent)

In my opinion it might happens, with a high probability, up to 1 / 25e-6 times per second - means <= 40000 per second! Based on that, let me disagree with your infrequent statement.

Off topic, I'm getting close to the beginning of my holiday, so I assume you can understand that we won't be able to continue this interesting discussion indefinitely.

@jepler
Copy link
Contributor

jepler commented Aug 8, 2020

do you agree that if two threads will try to execute the following line: https://github.com/LinuxCNC/linuxcnc/pull/912/files#diff-1e0916462e2abd03736e702b73ce6c11L1090 one of them will try to unlock unlocked lock?

How can this occur, when a thread's arrival at line 1090 requires that it hold the lock? Why should two threads both seen at line 1091 at the same time be taken as evidence of activity at line 1090 at the same time?

Let's continue looking at the simplified code I offered previously:

     1	f2() { 
     2	    while(1) {
     3	        lock();
     4	        unlock();
     5	        testcancel();
     6	    }
     7	}

Since you didn't specifically comment, I don't know whether you consider this to contain the essence of the LinuxCNC code. I believe f2 and f3 are equivalent, and that f3 is equivalent to what we already agreed was equivalent. If you don't see to the equivalence at some step or other, then it might be fruitful to focus on why that is, because it could help get at the root of our disagreement.

A precondition to arriving at line 4 is passing line 3. But a postcondition to completing line 3 is that this thread owns the lock. Therefore, the precondition to unlock() -- namely, that this thread owns the lock -- is met. Nothing stops two threads from being at other lines outside of 3..4, so no requirement is violated if both are seen at line 2, both at line 5, etc.

Enjoy your vacation. Let me close with some suggestions for moving beyond this even if we can't have a meeting of the minds about how the code functions.

  • Do the long-postponed review of the components that have multiple functions and those functions are intended to be placed in different threads; Rewrite them as necessary so they function correctly without Rate Monotonic Scheduling (for example by using atomic primitives that we didn't include originally).
    Once this is done, the thread_lock actually is unneeded and can be removed. It looks like this list is a bit longer than I thought: encoder, stepgen, sim-encoder, threadtest, encoder-ratio, pwmgen, process
    (another bonus for doing this is that we can investigate a long requested feature, being able to run each RT thread on a different CPU thread or core)
  • Split the "posix" realtime implementation into two classes, one for the SCHED_FIFO case and one for the SCHED_OTHER case. Relegate the code you're uneasy with further away from where you want to work, which is on the SCHED_FIFO case. This code predates extracting the virtual base class which enables the RTAI and Xenomai implementations, but logically speaking they are separate things that just happen to share some code.

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