title: pthread_mutex_lock waiting to lock a highly contented mutex exactly 60 seconds, if the mutex cant be locked immediately
body: <p>I am developing a shared memory IPC using C.</p>
  
  <p>In the design, a main server thread listens on a queue(called Main Request Queue) which is in shared memory and used for new connection requests. When each client process wants to connect to the server, it first try to lock a mutex on that queue and then put the request and then unlock the mutex.</p>
  
  <p>When I run many clients in parallel, say 100 clients, one or two of the clients, most of the time couldn't get mutex and wait exactly 60 seconds, before trying to get the lock. All other 99 or 98 clients, get access to mutex whenever it's free and continue it execution. The mutex won't be held more than 1ms, because only simple memcpy is happening... So something else is the problem, I am doubting that it's a bug in the implementation of pthread(Most probably it won't be, but still :) ).</p>
  
  <p>This is the backtrace in GDB when the client process waits on the mutex</p>
  
  <pre><code>#0  0x00007fa621bb7f1c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
  #1  0x00007fa621bb3649 in _L_lock_909 () from /lib/x86_64-linux-gnu/libpthread.so.0
  #2  0x00007fa621bb3470 in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
  #3  0x00007fa6207d4bdf in get_connection () at src/shm_ipc/ipc_req.c:24
  #4  0x00007fa6207d4dfa in RegisterConnection () at src/shm_ipc/ipc_req.c:87
  #5  0x00007fa6207db161 in IPC_Init () at src/shm_ipc/shm_rocksdb.c:10
  #6  0x00007fa6207c66bb in transitive_closure_pali (fcinfo=0x2d86158) at src/GraphIndex_Functions.c:50
  #7  0x00000000006c00b4 in ExecInterpExpr (state=0x2d86068, econtext=0x2d86678, isnull=0x7fff221d688c "") at execExprInterp.c:672
  #8  0x00000000007bd51d in ExecEvalExprSwitchContext (state=0x2d86068, econtext=0x2d86678, isNull=0x7fff221d688c "") at ../../../../src/include/executor/executor.h:308
  #9  0x00000000007c44d8 in evaluate_expr (expr=0x2d81ee8, result_type=25, result_typmod=-1, result_collation=100) at clauses.c:4735
  #10 0x00000000007c3906 in evaluate_function (funcid=287915, result_type=25, result_typmod=-1, result_collid=100, input_collid=0, args=0x2b7be38, funcvariadic=0 '\000', func_tuple=0x7fa6092c8278, 
      context=0x7fff221d7af0) at clauses.c:4292
  #11 0x00000000007c2e31 in simplify_function (funcid=287915, result_type=25, result_typmod=-1, result_collid=100, input_collid=0, args_p=0x7fff221d6a10, funcvariadic=0 '\000', process_args=1 '\001', 
      allow_non_const=1 '\001', context=0x7fff221d7af0) at clauses.c:3932
  #12 0x00000000007c08e7 in eval_const_expressions_mutator (node=0x2b7b9b8, context=0x7fff221d7af0) at clauses.c:2591
  #13 0x000000000072d236 in expression_tree_mutator (node=0x2b7ba10, mutator=0x7c0401 &lt;eval_const_expressions_mutator&gt;, context=0x7fff221d7af0) at nodeFuncs.c:2854
  #14 0x00000000007c2866 in eval_const_expressions_mutator (node=0x2b7ba10, context=0x7fff221d7af0) at clauses.c:3582
  #15 0x000000000072d428 in expression_tree_mutator (node=0x2b7ba68, mutator=0x7c0401 &lt;eval_const_expressions_mutator&gt;, context=0x7fff221d7af0) at nodeFuncs.c:2903
  #16 0x00000000007c2866 in eval_const_expressions_mutator (node=0x2b7ba68, context=0x7fff221d7af0) at clauses.c:3582
  #17 0x00000000007c03ae in eval_const_expressions (root=0x2b7bba0, node=0x2b7ba68) at clauses.c:2433
  #18 0x00000000007a1f70 in preprocess_expression (root=0x2b7bba0, expr=0x2b7ba68, kind=1) at planner.c:915
  #19 0x00000000007a1780 in subquery_planner (glob=0x2b7b6a0, parse=0x2b7b110, parent_root=0x0, hasRecursion=0 '\000', tuple_fraction=0) at planner.c:628
  #20 0x00000000007a0dcd in standard_planner (parse=0x2b7b110, cursorOptions=256, boundParams=0x0) at planner.c:334
  #21 0x00000000007a0b4a in planner (parse=0x2b7b110, cursorOptions=256, boundParams=0x0) at planner.c:210
  #22 0x0000000000889a03 in pg_plan_query (querytree=0x2b7b110, cursorOptions=256, boundParams=0x0) at postgres.c:796
  #23 0x0000000000889b30 in pg_plan_queries (querytrees=0x2b7bb68, cursorOptions=256, boundParams=0x0) at postgres.c:862
  #24 0x0000000000889e5a in exec_simple_query (query_string=0x2b79f70 "SELECT transitive_closure_pali('public.friendship','cd70a1b1-c203-42d7-ac3c-51b165fc3285','friends__id', 5);") at postgres.c:1027
  #25 0x000000000088e431 in PostgresMain (argc=1, argv=0x2ce6638, dbname=0x2ce6530 "postgres", username=0x2ce6508 "insaf-5680") at postgres.c:4090
  #26 0x00000000007ef252 in BackendRun (port=0x2cded70) at postmaster.c:4357
  #27 0x00000000007ee97c in BackendStartup (port=0x2cded70) at postmaster.c:4029
  #28 0x00000000007eaf42 in ServerLoop () at postmaster.c:1753
  #29 0x00000000007ea52e in PostmasterMain (argc=3, argv=0x2b5a6e0) at postmaster.c:1361
  #30 0x0000000000727e0c in main (argc=3, argv=0x2b5a6e0) at main.c:228
  </code></pre>
  
  <p>I am creating a postgres extension, so that's why the stacktrace contains other functions.</p>
  
  <p>get_connection() is calling pthread_mutex_lock(), functions.. The source code of get_connection() is given below:</p>
  
  <pre><code>static int get_connection(void)
  {
      int queue_id;
  
      while(1)
      {
          pthread_mutex_lock(&amp;(IPCComm-&gt;backend_queue_lock));
  
          for (queue_id = 0; queue_id &lt; MaxConnections; queue_id++)
          {
              if (IPCComm-&gt;backend_queue[queue_id].free)
              {
                  IPCComm-&gt;backend_queue[queue_id].free = false;
                  break;
              }
          }
  
          pthread_mutex_unlock(&amp;(IPCComm-&gt;backend_queue_lock));
  
          //If free connection has been got, break out of the loop, else sleep for some time and try again
          if(queue_id != MaxConnections)
              break;
          else
          {
              usleep(1000 * 10);
          }
      }
      return queue_id;
  }
  </code></pre>
  
  <p>What I've tried...
  If I signal the process somehow, like by attaching to it via gdb and then continuing, it gets the mutex quickly and continue execution. So it is kind of sleeping for 60seconds, I tried going through the glibc source code but couldn't find any code like that.</p>
  
  <p>My system details:</p>
  
  <pre><code>$ uname -vr
  4.2.0-36-generic #42~14.04.1-Ubuntu SMP Fri May 13 17:27:22 UTC 2016
  
  $ ldd --version
  ldd (Ubuntu EGLIBC 2.19-0ubuntu6.13) 2.19
  
  $ gcc --version
  gcc (Ubuntu 4.8.5-2ubuntu1~14.04.1) 4.8.5
  </code></pre>
  
  <p>Please help.</p>