Properly Functioning Timer Callback Execution

timer_callback_functioning.cpp

PWD=/data/users/imcmahon/dev/ros_core_ws/devel/lib/roscpp_tutorials
---Type <return> to continue, or q <return> to quit---q
Quit
(gdb) b 55
Breakpoint 1 at 0x403aee: file /data/users/imcmahon/dev/ros_core_ws/src/ros_tutorials/roscpp_tutorials/timers/timers.cpp, line 55.
(gdb) run
Starting program: /data/users/imcmahon/dev/ros_core_ws/devel/lib/roscpp_tutorials/timers 
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7ffff1881700 (LWP 6059)]
[New Thread 0x7ffff1080700 (LWP 6060)]
[New Thread 0x7ffff087f700 (LWP 6061)]
[New Thread 0x7fffebfff700 (LWP 6066)]

Breakpoint 1, main (argc=1, argv=0x7fffffffd578)
    at /data/users/imcmahon/dev/ros_core_ws/src/ros_tutorials/roscpp_tutorials/timers/timers.cpp:55
55	  ros::Timer timer1 = n.createTimer(ros::Duration(0.1), callback1);
(gdb) s
boost::function<void (ros::TimerEvent const&)>::function<void (*)(ros::TimerEvent const&)>(void (*)(ros::TimerEvent const&), boost::enable_if_c<boost::type_traits::ice_not<boost::is_integral<void (*)(ros::TimerEvent const&)>::value>::value, int>::type) (this=0x7fffffffd3a0, f=0x4037ad <callback1(ros::TimerEvent const&)>)
    at /usr/include/boost/function/function_template.hpp:1069
1069	    base_type(f)
(gdb) n
1071	  }
(gdb) n
[New Thread 0x7fffeb7fe700 (LWP 6072)]
main (argc=1, argv=0x7fffffffd578)
    at /data/users/imcmahon/dev/ros_core_ws/src/ros_tutorials/roscpp_tutorials/timers/timers.cpp:56
56	  ros::Timer timer2 = n.createTimer(ros::Duration(1.0), callback2);
(gdb) n
59	  ros::spin();
(gdb) s
ros::spin () at /data/users/imcmahon/dev/ros_core_ws/src/ros_comm/clients/roscpp/src/libros/init.cpp:527
527	  SingleThreadedSpinner s;
(gdb) n
528	  spin(s);
(gdb) s
ros::spin (s=...) at /data/users/imcmahon/dev/ros_core_ws/src/ros_comm/clients/roscpp/src/libros/init.cpp:533
533	  s.spin();
(gdb) s
ros::SingleThreadedSpinner::spin (this=0x7fffffffd310, queue=0x0)
    at /data/users/imcmahon/dev/ros_core_ws/src/ros_comm/clients/roscpp/src/libros/spinner.cpp:45
45	  boost::recursive_mutex::scoped_try_lock spinlock(spinmutex);
(gdb) s
boost::detail::try_lock_wrapper<boost::recursive_mutex>::try_lock_wrapper (this=0x7fffffffd200, m=...)
    at /usr/include/boost/thread/lock_types.hpp:1133
1133	    base(m,try_to_lock)
(gdb) n
1134	    {}
(gdb) n
ros::SingleThreadedSpinner::spin (this=0x7fffffffd310, queue=0x0)
    at /data/users/imcmahon/dev/ros_core_ws/src/ros_comm/clients/roscpp/src/libros/spinner.cpp:46
46	  if(!spinlock.owns_lock()) {
(gdb) n
52	  ros::WallDuration timeout(0.1f);
(gdb) n
54	  if (!queue)
(gdb) n
56	    queue = getGlobalCallbackQueue();
(gdb) n
59	  ros::NodeHandle n;
(gdb) print queue
$1 = (ros::CallbackQueue *) 0x60f2a0
(gdb) n
60	  while (n.ok())
(gdb) n
62	    queue->callAvailable(timeout);
(gdb) s
ros::CallbackQueue::callAvailable (this=0x60f2a0, timeout=...)
    at /data/users/imcmahon/dev/ros_core_ws/src/ros_comm/clients/roscpp/src/libros/callback_queue.cpp:292
292	  setupTLS();
(gdb) n
293	  TLS* tls = tls_.get();
(gdb) n
296	    boost::mutex::scoped_lock lock(mutex_);
(gdb) n
298	    if (!enabled_)
(gdb) n
303	    if (callbacks_.empty())
(gdb) n
316	    bool was_empty = tls->callbacks.empty();
(gdb) n
318	    tls->callbacks.insert(tls->callbacks.end(), callbacks_.begin(), callbacks_.end());
(gdb) n
319	    callbacks_.clear();
(gdb) n
321	    calling_ += tls->callbacks.size();
(gdb) n
323	    if (was_empty)
(gdb) n
325	      tls->cb_it = tls->callbacks.begin();
(gdb) n
326	    }
(gdb) n
329	  size_t called = 0;
(gdb) n
331	  while (!tls->callbacks.empty())
(gdb) n
333	    if (callOneCB(tls) != Empty)
(gdb) n
[ INFO] [1441056691.831686818]: Callback 1 triggered
335	      ++called;
(gdb) n
331	  while (!tls->callbacks.empty())
(gdb) n
333	    if (callOneCB(tls) != Empty)
(gdb) s
ros::CallbackQueue::callOneCB (this=0x60f2a0, tls=0x61a1a0)
    at /data/users/imcmahon/dev/ros_core_ws/src/ros_comm/clients/roscpp/src/libros/callback_queue.cpp:349
349	  if (tls->calling_in_this_thread == 0xffffffffffffffffULL)
(gdb) n
351	    tls->cb_it = tls->callbacks.begin();
(gdb) n
354	  if (tls->cb_it == tls->callbacks.end())
(gdb) n
359	  ROS_ASSERT(!tls->callbacks.empty());
(gdb) n
360	  ROS_ASSERT(tls->cb_it != tls->callbacks.end());
(gdb) n
362	  CallbackInfo info = *tls->cb_it;
(gdb) n
363	  CallbackInterfacePtr& cb = info.callback;
(gdb) print info
$2 = {callback = {px = 0x7fffe0000ae0, pn = {pi_ = 0x7fffe0000b30}}, removal_id = 6405040, marked_for_removal = false}
(gdb) n
365	  IDInfoPtr id_info = getIDInfo(info.removal_id);
(gdb) n
366	  if (id_info)
(gdb) n
368	    boost::shared_lock<boost::shared_mutex> rw_lock(id_info->calling_rw_mutex);
(gdb) n
370	    uint64_t last_calling = tls->calling_in_this_thread;
(gdb) n
371	    tls->calling_in_this_thread = id_info->id;
(gdb) n
373	    CallbackInterface::CallResult result = CallbackInterface::Invalid;
(gdb) n
375	      if (info.marked_for_removal)
(gdb) n
381	        tls->cb_it = tls->callbacks.erase(tls->cb_it);
(gdb) n
382	        result = cb->call();
(gdb) n
[ INFO] [1441056798.935178020]: Callback 2 triggered
392	    tls->calling_in_this_thread = last_calling;
(gdb) n
395	    if (result == CallbackInterface::TryAgain && !info.marked_for_removal)
(gdb) n
403	    return Called;
(gdb) n
365	  IDInfoPtr id_info = getIDInfo(info.removal_id);
(gdb) n
410	  return Called;
(gdb) n
411	}
(gdb) n
ros::CallbackQueue::callAvailable (this=0x60f2a0, timeout=...)
    at /data/users/imcmahon/dev/ros_core_ws/src/ros_comm/clients/roscpp/src/libros/callback_queue.cpp:335
335	      ++called;
(gdb) n
331	  while (!tls->callbacks.empty())
(gdb)