Section 20.5. Task Queue Observability

20.5. Task Queue Observability

20.5.1. Kstat Counters

Every taskq created in the system keeps a set of associated kstat counters. Try running the following command on your system.

sol9$ kstat -c taskq module: unix                            instance: 0 name:   ata_nexus_enum_tq               class:    taskq         crtime                          53.877907833         executed                        0         maxtasks                        0         nactive                         1         nalloc                          0         priority                        60         snaptime                        258059.249256749         tasks                           0         threads                         1         totaltime                       0 module: unix                            instance: 0 name:   callout_taskq                   class:    taskq         crtime                          0         executed                        13956358         maxtasks                        4         nactive                         4         nalloc                          0         priority                        99         snaptime                        258059.24981709         tasks                           13956358         threads                         2         totaltime                       120247890619  ... 

The kstat information above includes

• Name of the taskq and its instance number

• Number of scheduled and executed tasks

• Number of kernel threads processing the taskq and their priority

• Total time (in nanoseconds) spent processing all the tasks

You can use the power of the kstat command to observe how some counter increases over time.

sol9$ kstat -p unix:0:callout_taskq:tasks 1 5 unix:0:callout_taskq:tasks      13994642 unix:0:callout_taskq:tasks      13994711 unix:0:callout_taskq:tasks      13994784 unix:0:callout_taskq:tasks      13994855 unix:0:callout_taskq:tasks      13994926 ... 

20.5.2. DTrace SDT Probes

The taskq implementation also provides several useful SDT probes. The probes described below have two arguments: the taskq pointer and the pointer to the taskq_ent_t structure, which can extract the function and the argument from the D script.

• taskq-enqueue probe fires whenever a task is queued on the taskq.

• taskq-exec-start probe fires just before the task is about to be executed.

• taskq-exec-end probe fires immediately after the task is executed.

Developers can use these probes to collect precise timing information about individual task queues and individual tasks being executed through them. For example, the following script prints the functions that were scheduled through task queues every 10 seconds.

#!/usr/sbin/dtrace -qs sdt:genunix::taskq-enqueue {   this->tq  = (taskq_t *)arg0;   this->tqe = (taskq_ent_t *) arg1;   @[this->tq->tq_name,     this->tq->tq_instance,     this->tqe->tqent_func] = count(); } tick-10s {   printa ("%s(%d): %a called %@d times\n", @);   trunc(@); } 

Running this on a desktop produced the following output.

callout_taskq(1): genunix`callout_execute called 51 times callout_taskq(0): genunix`callout_execute called 701 times kmem_taskq(0): genunix`kmem_update_timeout called 1 times kmem_taskq(0): genunix`kmem_hash_rescale called 4 times callout_taskq(1): genunix`callout_execute called 40 times USB_hid_81_pipehndl_tq_1(14): usba`hcdi_cb_thread called 256 times callout_taskq(0): genunix`callout_execute called 702 times kmem_taskq(0): genunix`kmem_update_timeout called 1 times kmem_taskq(0): genunix`kmem_hash_rescale called 4 times callout_taskq(1): genunix`callout_execute called 28 times USB_hid_81_pipehndl_tq_1(14): usba`hcdi_cb_thread called 228 times callout_taskq(0): genunix`callout_execute called 706 times callout_taskq(1): genunix`callout_execute called 24 times USB_hid_81_pipehndl_tq_1(14): usba`hcdi_cb_thread called 141 times callout_taskq(0): genunix`callout_execute called 708 times