diff --git a/source/development/how-tos/dtrace.rst b/source/development/how-tos/dtrace.rst new file mode 100755 index 00000000..a7af424e --- /dev/null +++ b/source/development/how-tos/dtrace.rst @@ -0,0 +1,219 @@ +============================== +Profiling/Debugging the kernel +============================== + +-------- +Overview +-------- + +Kernel development often involves writing code without an IDE. Even if an IDE is used, +proper profiling support is often lacking. Luckily, FreeBSD includes DTrace. + +Since OPNsense runs on a fork of FreeBSD, DTrace is natively available on the +system for developers to use in debugging and profiling. To quote the FreeBSD handbook on DTrace: + +:: + + “DTrace, also known as Dynamic Tracing, was developed by Sun™ as a tool + for locating performance bottlenecks in production and pre-production + systems. In addition to diagnosing performance problems, DTrace can be used + to help investigate and debug unexpected behavior in both the FreeBSD kernel + and in userland programs. + + DTrace is a remarkable profiling tool, with an impressive array of features + for diagnosing system issues. It may also be used to run pre-written scripts + to take advantage of its capabilities. Users can author their own utilities + using the DTrace D Language, allowing them to customize their profiling based + on specific needs.” + + +We will be looking at setting up DTrace on OPNsense, and running a sample script +to perform some useful analysis on kernel space. An example for generating a FlameGraph +will also be presented. Keep in mind that user space can also be analyzed using DTrace, +but this is beyond the scope of this document. + +Although detailed steps for enabling DTrace in a custom kernel are widely available, +this document provides an explanation in combination with the use of OPNsense-specific tools. +Further resources will be provided at the end of this document. + +.. note:: + + All generic DTrace concepts, as well as default probe providers are + documented `here `__. + If you are interested in using DTrace to profile performance issues, we suggest reading + the documentation before proceeding. We will not go into too much detail here to prevent + cluttering the document and keep it simple and to-the-point. + +--------------- +Enabling DTrace +--------------- + +Make sure the OPNsense/src repository is present on the system and navigate to +:code:`/usr/src/sys/[ARCHITECTURE, e.g. amd64]/conf` and open up :code:`GENERIC`. +Add the following options: + +.. code-block:: sh + + makeoptions DEBUG=-g # Will build a debug kernel (using gdb debug symbols) + makeoptions WITH_CTF=1 # Adds CTF type data to built executables + options KDTRACE_FRAME # Ensure frames are compiled in + +.. note:: + + CTF type data is described + `here `__. + The idea is to represent the types used in a C program within the executable, + allowing users of DTrace to access symbols and function parameters during runtime. + +As a best practice, under stock FreeBSD you would save the file under a different name +(e.g. DTRACE) and build the kernel by specifying :code:`KERNCONF=DTRACE`. +The opnsense-tools require the name to be :code:`GENERIC`, so we will leave it as is. +It is advisable to create a backup of the original :code:`GENERIC` file though. +Make sure the OPNsense-tools repository is installed and navigate to :code:`/usr/tools/config/[VERSION]`. +Open up :code:`SMP` and make sure the following line is either removed or commented out: + +.. code-block:: sh + + nomakeoptions DEBUG + +Furthermore, should you wish to enable DTrace in Userspace, it is imperative that you also +add the following line to :code:`/usr/tools/conf/[VERSION]/make.conf` + +.. code-block:: sh + + STRIP= + CFLAGS+=-fno-omit-frame-pointer + +Now clean and build the new kernel + +.. code-block:: sh + + # make clean-obj,kernel kernel + +A kernel package will be available at the following location: + + :code:`/usr/local/opnsense/build/[Version]/[Architecture]/sets/kernel*.txz` + +Install the package using our :code:`opnsense-update` command: + +.. code-block:: sh + + # opnsense-update -ikfr [version] -l /location/from/ + +Where [version] is the version part of the kernel package, such as :code:`21.1.a_83` + +--------------------- +Test the installation +--------------------- + +Follow the steps described in the section 'Getting Started' `here `__ + +-------------- +DTrace program +-------------- + +Although it is possible to instruct DTrace to execute a certain function on the +command line (and there are a lot of one-liners for this `here `__), instead we present a D script that measures some statistics on the ixgbe 10GbE driver and +shows some interesting capabilities of DTrace in one go. Specifically, it measures the amount +of interrupts fired on the packet receive side, as well as the time spent in the relevant functions +in nanoseconds. It also measures how many threads on average are waiting to be serviced because +another thread is busy. + +.. literalinclude:: ./files/example.d + :language: D + +The one-line command to pre-process, compile and run the script is: + +.. code-block:: sh + + # dtrace -C -s example.d + +The :code:`-C` option specifies that the standard C preprocessor should evaluate the file, ensuring +that the C-specific code like macro definitions are defined. + +The output (when pinging the device): + +.. image:: ./images/dtrace_output_docs.png + :alt: Dtrace Output + +Notice how the queue behaviour section shows no output, this is because there is no actual +queue behaviour going on. There is simply too little traffic for the kernel to be queueing threads. +When stressing the driver, it might look something like this: + +.. image:: ./images/queue_behaviour.png + :alt: Queue behaviour + +------------ +Flame Graphs +------------ + +If you run the following command: + +.. code-block:: sh + + # dtrace -n uiomove:entry'{ @[stack] = count(); }' + +Let it run for a while, and exit using :code:`CTRL-C` + +You will see all `stack frames `__ associated with +:code:`uiomove()` that have taken place, aggregated to only unique frames. The number below the individual +frame represents the amount of times that particular frame was executed. Although this is nice, +it isn't particulary visually pleasing or helpful in spotting potential bottlenecks. + +A senior performance analyst at Netflix, named Brendan Gregg, developed the +`FlameGraph `__ for use with DTrace (and other profiling tools). +The program consists of a set of Perl files that take in the data produced by a command +similar to the one we executed, and generate a graph that helps spot 'hot code paths'. +This time however, we will look at the kernel as a whole and sample it in a set interval. + +1. Clone the `repository `__ and instruct dtrace to +sample kernel stacks at a rate of 997 Hertz for 60 seconds: + +.. code-block:: sh + + # dtrace -x stackframes=100 -n 'profile-997 /arg0/ { @[stack()] = count(); } tick-60s { exit(0); }' -o out.kern_stacks + +2. Collapse the individual lines in the output file by folding it into single lines: + +.. code-block:: sh + + # ./stackcollapse.pl out.kern_stacks > out.kern_folded + +Having a separate folded input file allows for grepping functions of interest: + +.. code-block:: sh + + # grep cpuid out.kern_folded | ./flamegraph.pl > cpuid.svg + +.. note:: + + If you get the message "Command not found", use the command + :code:`perl stackcollapse.pl out.kern_stacks > out.kern_folded` + +3. Generate a flame graph: + +.. code-block:: sh + + # ./flamegraph.pl out.kern_folded > kernel.svg + +.. image:: ./images/example-dtrace.svg + :alt: FlameGraph + +The output image is an SVG file, enabling interaction within a browser. + +--------------- +Other Resources +--------------- +Brendan Gregg's collection of DTrace programs: +http://www.brendangregg.com/dtrace.html + +Using the right datatypes in DTrace to increase profiling performance: +http://dtrace.org/blogs/brendan/2011/11/25/dtrace-variable-types/ + +FreeBSD DTrace manual page: +https://www.freebsd.org/cgi/man.cgi?query=dtrace + +FreeBSD DTrace one-liners: +https://wiki.freebsd.org/DTrace/One-Liners + + diff --git a/source/development/how-tos/files/example.d b/source/development/how-tos/files/example.d new file mode 100644 index 00000000..f5b4b871 --- /dev/null +++ b/source/development/how-tos/files/example.d @@ -0,0 +1,252 @@ + +/* RX threads, retrieved from procstat -a -t, listing thread information for all (kernel) processes */ +inline int qg0 = 100018; +inline int qg1 = 100019; +inline int qg2 = 100020; +inline int qg3 = 100021; +inline int qg4 = 100022; +inline int qg5 = 100023; +inline int qg6 = 100024; +inline int qg7 = 100025; + +/* Because of this preprocessor statement, this script should be compiled with -C option */ +#define PROBE_PREDICATE \ + pid == 0 && \ + (tid == qg0 || \ + tid == qg1 || \ + tid == qg2 || \ + tid == qg3 || \ + tid == qg4 || \ + tid == qg5 || \ + tid == qg6 || \ + tid == qg7) \ + \ + + +#define DRIVER_CHECK self->driver_prefix == "ix" + +/********************************************/ +/* Iflib rx info & interrupt info */ +/********************************************/ + +struct iflib_intr_info { + uint64_t fast_intr_ts; + uint64_t fast_intr_elapsed; + uint64_t filter_routine_ts; + uint64_t task_tx_ts; +}; + +struct iflib_intr_info ii[int]; + +struct iflib_task_info { + uint64_t task_rx_ts; + uint64_t rxeof_ts; +}; + +struct iflib_task_info iti[int]; + +/* RX (and TX) interrupt entry point, will call driver supplied filter */ +fbt::iflib_fast_intr:entry +{ + ii[tid].fast_intr_ts = timestamp; + this->info = ((kernel`iflib_filter_info_t)arg0); + self->rxq_id = (uint16_t)((kernel`iflib_rxq_t)this->info->ifi_ctx)->ifr_id; + @intcounts[tid, self->rxq_id, probefunc] = count(); + +} + +fbt::iflib_fast_intr:return +/ii[tid].fast_intr_ts/ +{ + @time[tid, self->rxq_id, probefunc] = avg(timestamp - ii[tid].fast_intr_ts); + @fi_time_min[tid, self->rxq_id, probefunc] = min(timestamp - ii[tid].fast_intr_ts); + @fi_time_max[tid, self->rxq_id, probefunc] = max(timestamp - ii[tid].fast_intr_ts); +} + +/* axgbe driver filter routine */ +fbt::axgbe_msix_que:entry, fbt::ixgbe_msix_que:entry +{ + ii[tid].filter_routine_ts = timestamp; + @intcounts[tid, self->rxq_id, probefunc] = count(); +} + +fbt::axgbe_msix_que:return, fbt::ixgbe_msix_que:return +/ii[tid].filter_routine_ts/ +{ + @fr_time_avg[tid, self->rxq_id, probefunc] = avg(timestamp - ii[tid].filter_routine_ts); + @fr_time_min[tid, self->rxq_id, probefunc] = min(timestamp - ii[tid].filter_routine_ts); + @fr_time_max[tid, self->rxq_id, probefunc] = max(timestamp - ii[tid].filter_routine_ts); +} + + +/* + * at this point, iflib has enqueued the _task_fn_rx / _task_fn_tx function, + * we could measure some relevant things here. + * The threads that run the queued functions are all in the range of the threads + * defined at the top of this file + * We could also inspect the queue structure to determine the average amount of functions + * waiting to be serviced, this information could be pulled out of the iflib interrupt handler + * Also, the thread that runs the queued function is different from the thread that runs the interrupt handler, + * so query again for the relevant drivers and include it in the probe predicates + */ + +char *driver_name[2]; + + +fbt::_task_fn_rx:entry +/PROBE_PREDICATE && (!self->prefix_set)/ +{ + + + /* get taskqueue structure information to determine amount of functions waiting to be serviced */ + this->rxq = ((kernel`iflib_rxq_t)arg0); + this->grouptask = (struct grouptask)(this->rxq->ifr_task); + self->gt_name = stringof(this->grouptask.gt_name); + this->if_ctx = (if_ctx_t)(this->rxq)->ifr_ctx; + this->dev = (device_t)(this->if_ctx)->ifc_dev; + this->driver = (driver_t *)(this->dev)->driver; + driver_name[0] = (const char *)(this->driver)->name; + driver_name[1] = (const char *)(this->driver)->name + 1; + self->driver_prefix = stringof(*(driver_name)); + self->prefix_set = 1; + +} + +fbt::_task_fn_rx:entry +/PROBE_PREDICATE && DRIVER_CHECK/ +{ + iti[tid].task_rx_ts = timestamp; + @_task_fn_rx_count[tid, self->gt_name, probefunc] = count(); +} + +fbt::_task_fn_rx:return +/PROBE_PREDICATE && iti[tid].task_rx_ts && DRIVER_CHECK/ +{ + @task_rx_avg[tid, self->gt_name, probefunc] = avg(timestamp - iti[tid].task_rx_ts); + @task_rx_min[tid, self->gt_name, probefunc] = min(timestamp - iti[tid].task_rx_ts); + @task_rx_max[tid, self->gt_name, probefunc] = max(timestamp - iti[tid].task_rx_ts); +} + + +fbt::iflib_rxeof:entry +/PROBE_PREDICATE && DRIVER_CHECK/ +{ + iti[tid].rxeof_ts = timestamp; + @rxeof_count[tid, self->gt_name, probefunc] = count(); + +} + +fbt::iflib_rxeof:return +/PROBE_PREDICATE && iti[tid].rxeof_ts && DRIVER_CHECK/ +{ + @rxeof_avg[tid, self->gt_name, probefunc] = avg(timestamp - iti[tid].rxeof_ts); + @rxeof_min[tid, self->gt_name, probefunc] = min(timestamp - iti[tid].rxeof_ts); + @rxeof_max[tid, self->gt_name, probefunc] = max(timestamp - iti[tid].rxeof_ts); + +} + +fbt::ixgbe_isc_rxd_refill:entry +/PROBE_PREDICATE && DRIVER_CHECK/ +{ + this->ts = timestamp; + @rxd_refill_count[tid, self->gt_name, probefunc] = count(); +} + +fbt::ixgbe_isc_rxd_refill:return +/PROBE_PREDICATE && this->ts && DRIVER_CHECK/ +{ + + @rxd_refill_avg[tid, self->gt_name, probefunc] = avg(timestamp - this->ts); + @rxd_refill_min[tid, self->gt_name, probefunc] = min(timestamp - this->ts); + @rxd_refill_max[tid, self->gt_name, probefunc] = max(timestamp - this->ts); +} + + +/* notice how the ixgbe driver is missing, this is because of the dtrace compiler optimization - the return probe is missing */ +fbt::ixgbe_isc_rxd_available:entry +/PROBE_PREDICATE && DRIVER_CHECK/ +{ + this->ts = timestamp; + @rxd_avail_count[tid, self->gt_name, probefunc] = count(); +} + +fbt::ixgbe_isc_rxd_available:return +/PROBE_PREDICATE && (this->ts != 0) && DRIVER_CHECK/ +{ + @rxd_avail_avg[tid, self->gt_name, probefunc] = avg(timestamp - this->ts); + @rxd_avail_min[tid, self->gt_name, probefunc] = min(timestamp - this->ts); + @rxd_avail_max[tid, self->gt_name, probefunc] = max(timestamp - this->ts); +} + +fbt::ixgbe_isc_rxd_pkt_get:entry +/PROBE_PREDICATE && DRIVER_CHECK/ +{ + this->ts = timestamp; + @rxd_pkt_get_count[tid, self->gt_name, probefunc] = count(); +} + +fbt::ixgbe_isc_rxd_pkt_get:return +/PROBE_PREDICATE && (this->ts != 0) && DRIVER_CHECK/ +{ + @rxd_pkt_get_avg[tid, self->gt_name, probefunc] = avg(timestamp - this->ts); + @rxd_pkt_get_min[tid, self->gt_name, probefunc] = min(timestamp - this->ts); + @rxd_pkt_get_max[tid, self->gt_name, probefunc] = max(timestamp - this->ts); +} + + +/********************************************/ +/* Queue behaviour */ +/********************************************/ + +int qlen[int]; + +/* enqueue and deqeueue probes to determine the run length of the queues */ +sched:::enqueue +/PROBE_PREDICATE && DRIVER_CHECK/ +{ + this->q_len = qlen[tid]++; + + @q_len_all_threads_avg[tid] = avg(this->q_len); + @q_len_all_threads_min[tid] = min(this->q_len); + @q_len_all_threads_max[tid] = max(this->q_len); +} + +sched:::dequeue +/PROBE_PREDICATE && qlen[tid] && DRIVER_CHECK/ +{ + qlen[tid]--; + +} + + +END +{ + printf("\n"); + printf("\n"); + printf("\n"); + printf("\n"); + printf("-------INTERRUPTS-------\n"); + printf("\n"); + printf("thread core function count avg time(ns) min time max time avg time(driver) min time(driver) max time(driver)\n"); + printf("------ ---- --------------------- --------------- ------------ -------- -------- ---------------- ---------------- ----------------\n"); + printa("%6d %4d %21s %@15d %@12d %@8d %@8d %@16d %@16d %@16d\n", @intcounts, @time, @fi_time_min, @fi_time_max, @fr_time_avg, @fr_time_min, @fr_time_max); + printf("\n"); + + printf("-------DRIVER/IFLIB FUNCTIONS RX-------\n"); + printf("thread grouptask name function avg time(ns) min time(ns) max time(ns) count\n"); + printf("------ -------------- ------------------------------ ------------ ------------ ------------ -----------\n"); + printa("%6d %14s %30s %@12d %@12d %@12d %@11d\n", @task_rx_avg, @task_rx_min, @task_rx_max, @_task_fn_rx_count); + printa("%6d %14s %30s %@12d %@12d %@12d %@11d\n", @rxeof_avg, @rxeof_min, @rxeof_max, @rxeof_count); + printa("%6d %14s %30s %@12d %@12d %@12d %@11d\n", @rxd_refill_avg, @rxd_refill_min, @rxd_refill_max, @rxd_refill_count); + printa("%6d %14s %30s %@12d %@12d %@12d %@11d\n", @rxd_avail_avg, @rxd_avail_min, @rxd_avail_max, @rxd_avail_count); + printa("%6d %14s %30s %@12d %@12d %@12d %@11d\n", @rxd_pkt_get_avg, @rxd_pkt_get_min, @rxd_pkt_get_max, @rxd_pkt_get_count); + printf("\n"); + + + printf("---------QUEUE BEHAVIOUR---------\n"); + printf("thread avg run length min run length max run length\n"); + printf("------ -------------- -------------- --------------\n"); + printa("%6d %@14d %@14d %@14d\n", @q_len_all_threads_avg, @q_len_all_threads_min, @q_len_all_threads_max); + printf("\n"); +} + diff --git a/source/development/how-tos/images/dtrace_output_docs.png b/source/development/how-tos/images/dtrace_output_docs.png new file mode 100755 index 00000000..ab3037f4 Binary files /dev/null and b/source/development/how-tos/images/dtrace_output_docs.png differ diff --git a/source/development/how-tos/images/example-dtrace.svg b/source/development/how-tos/images/example-dtrace.svg new file mode 100755 index 00000000..6702dc8b --- /dev/null +++ b/source/development/how-tos/images/example-dtrace.svg @@ -0,0 +1,1842 @@ + + + + + + + + + + + + + +Flame Graph + +Reset Zoom +Search + +unix`mutex_enter (195 samples, 0.34%) + + + +genunix`as_fault (12 samples, 0.02%) + + + +genunix`disp_lock_exit (27 samples, 0.05%) + + + +genunix`vsd_free (17 samples, 0.03%) + + + +genunix`pn_fixslash (44 samples, 0.08%) + + + +unix`mutex_exit (105 samples, 0.18%) + + + +genunix`falloc (1,363 samples, 2.37%) +g.. + + +genunix`traverse (30 samples, 0.05%) + + + +genunix`fop_lookup (55 samples, 0.10%) + + + +genunix`kmem_cache_free (29 samples, 0.05%) + + + +lofs`makelonode (39 samples, 0.07%) + + + +genunix`vsd_free (155 samples, 0.27%) + + + +unix`strlen (2,659 samples, 4.63%) +unix`.. + + +unix`clear_int_flag (180 samples, 0.31%) + + + +unix`mutex_exit (38 samples, 0.07%) + + + +genunix`kmem_cpu_reload (5 samples, 0.01%) + + + +unix`mutex_exit (26 samples, 0.05%) + + + +genunix`vn_vfslocks_getlock (47 samples, 0.08%) + + + +unix`bzero (8 samples, 0.01%) + + + +genunix`vn_exists (50 samples, 0.09%) + + + +unix`mutex_enter (727 samples, 1.27%) + + + +genunix`kmem_cache_alloc (179 samples, 0.31%) + + + +unix`mutex_enter (905 samples, 1.58%) + + + +genunix`ufalloc (10 samples, 0.02%) + + + +genunix`vn_rele (25 samples, 0.04%) + + + +genunix`vn_exists (17 samples, 0.03%) + + + +unix`lock_try (778 samples, 1.35%) + + + +genunix`rwst_enter_common (314 samples, 0.55%) + + + +genunix`fsop_root (62 samples, 0.11%) + + + +lofs`table_lock_enter (44 samples, 0.08%) + + + +unix`mutex_exit (138 samples, 0.24%) + + + +unix`mutex_enter (316 samples, 0.55%) + + + +genunix`kmem_cache_free (5 samples, 0.01%) + + + +unix`preempt (14 samples, 0.02%) + + + +genunix`vn_alloc (1,189 samples, 2.07%) +g.. + + +genunix`kmem_cache_alloc (126 samples, 0.22%) + + + +genunix`vfs_getops (157 samples, 0.27%) + + + +lofs`lsave (27 samples, 0.05%) + + + +unix`tsc_read (160 samples, 0.28%) + + + +lofs`lfind (26 samples, 0.05%) + + + +unix`atomic_add_64 (205 samples, 0.36%) + + + +unix`mutex_enter (320 samples, 0.56%) + + + +genunix`traverse (17 samples, 0.03%) + + + +unix`mutex_enter (197 samples, 0.34%) + + + +genunix`vn_mountedvfs (20 samples, 0.03%) + + + +genunix`audit_unfalloc (340 samples, 0.59%) + + + +genunix`kmem_cache_free (209 samples, 0.36%) + + + +genunix`kmem_zalloc (13 samples, 0.02%) + + + +genunix`thread_lock (33 samples, 0.06%) + + + +unix`tsc_read (186 samples, 0.32%) + + + +genunix`vn_vfsrlock (12 samples, 0.02%) + + + +lofs`lo_inactive (21 samples, 0.04%) + + + +genunix`rwst_destroy (20 samples, 0.03%) + + + +unix`mutex_enter (379 samples, 0.66%) + + + +genunix`vn_setops (41 samples, 0.07%) + + + +genunix`vn_recycle (33 samples, 0.06%) + + + +lofs`lo_inactive (6,307 samples, 10.98%) +lofs`lo_inactive + + +lofs`table_lock_enter (220 samples, 0.38%) + + + +genunix`cv_broadcast (25 samples, 0.04%) + + + +unix`mutex_exit (358 samples, 0.62%) + + + +genunix`kmem_cache_alloc (234 samples, 0.41%) + + + +unix`rw_enter (525 samples, 0.91%) + + + +unix`membar_consumer (237 samples, 0.41%) + + + +unix`swtch (5 samples, 0.01%) + + + +genunix`rwst_enter_common (32 samples, 0.06%) + + + +lofs`freelonode (5,313 samples, 9.25%) +lofs`freelonode + + +genunix`vn_openat (46,342 samples, 80.68%) +genunix`vn_openat + + +genunix`vn_rele (19 samples, 0.03%) + + + +genunix`proc_exit (5 samples, 0.01%) + + + +unix`mutex_exit (512 samples, 0.89%) + + + +genunix`kmem_free (35 samples, 0.06%) + + + +unix`mutex_enter (252 samples, 0.44%) + + + +genunix`rwst_exit (12 samples, 0.02%) + + + +genunix`crgetuid (22 samples, 0.04%) + + + +genunix`kmem_free (17 samples, 0.03%) + + + +unix`mutex_init (53 samples, 0.09%) + + + +ufs`ufs_iaccess (648 samples, 1.13%) + + + +all (57,441 samples, 100%) + + + +genunix`fop_inactive (6,689 samples, 11.64%) +genunix`fop_inact.. + + +genunix`kmem_cache_alloc (9 samples, 0.02%) + + + +genunix`kmem_cache_free (184 samples, 0.32%) + + + +genunix`pn_get_buf (13 samples, 0.02%) + + + +unix`strlen (107 samples, 0.19%) + + + +unix`mutex_exit (46 samples, 0.08%) + + + +genunix`post_syscall (12 samples, 0.02%) + + + +unix`mutex_init (38 samples, 0.07%) + + + +unix`rw_exit (439 samples, 0.76%) + + + +lofs`lo_lookup (65 samples, 0.11%) + + + +genunix`clear_stale_fd (44 samples, 0.08%) + + + +unix`mutex_enter (238 samples, 0.41%) + + + +genunix`pn_get_buf (687 samples, 1.20%) + + + +genunix`vn_free (1,663 samples, 2.90%) +ge.. + + +unix`mutex_enter (980 samples, 1.71%) + + + +genunix`crhold (5 samples, 0.01%) + + + +unix`mutex_exit (59 samples, 0.10%) + + + +genunix`vn_reinit (48 samples, 0.08%) + + + +genunix`vfs_getops (21 samples, 0.04%) + + + +genunix`open (49,669 samples, 86.47%) +genunix`open + + +genunix`kmem_cache_alloc (39 samples, 0.07%) + + + +genunix`vn_vfslocks_getlock (79 samples, 0.14%) + + + +unix`clear_int_flag (39 samples, 0.07%) + + + +genunix`kmem_cache_free (215 samples, 0.37%) + + + +unix`mutex_destroy (53 samples, 0.09%) + + + +genunix`vn_vfsunlock (3,578 samples, 6.23%) +genunix`.. + + +genunix`dnlc_lookup (1,843 samples, 3.21%) +gen.. + + +genunix`lookupnameatcred (45,978 samples, 80.04%) +genunix`lookupnameatcred + + +genunix`crgetmapped (41 samples, 0.07%) + + + +genunix`anon_zero (7 samples, 0.01%) + + + +genunix`rwst_tryenter (628 samples, 1.09%) + + + +unix`mutex_enter (309 samples, 0.54%) + + + +genunix`vn_rele (14 samples, 0.02%) + + + +genunix`vn_setpath (1,969 samples, 3.43%) +gen.. + + +unix`mutex_enter (111 samples, 0.19%) + + + +genunix`cv_broadcast (40 samples, 0.07%) + + + +genunix`kmem_cache_alloc (66 samples, 0.11%) + + + +genunix`audit_getstate (21 samples, 0.04%) + + + +genunix`vn_setpath (58 samples, 0.10%) + + + +genunix`open (17 samples, 0.03%) + + + +unix`bcopy (896 samples, 1.56%) + + + +unix`mutex_enter (99 samples, 0.17%) + + + +genunix`traverse (5,557 samples, 9.67%) +genunix`traverse + + +genunix`pn_getcomponent (41 samples, 0.07%) + + + +unix`mutex_enter (640 samples, 1.11%) + + + +unix`mutex_destroy (176 samples, 0.31%) + + + +unix`lwp_getdatamodel (6 samples, 0.01%) + + + +genunix`unfalloc (39 samples, 0.07%) + + + +genunix`syscall_mstate (355 samples, 0.62%) + + + +genunix`cv_init (65 samples, 0.11%) + + + +unix`mutex_enter (95 samples, 0.17%) + + + +unix`bcmp (42 samples, 0.07%) + + + +unix`mutex_exit (350 samples, 0.61%) + + + +genunix`kmem_free (288 samples, 0.50%) + + + +unix`mutex_exit (58 samples, 0.10%) + + + +genunix`kmem_alloc (32 samples, 0.06%) + + + +unix`mutex_exit (356 samples, 0.62%) + + + +unix`mutex_init (46 samples, 0.08%) + + + +genunix`rwst_init (173 samples, 0.30%) + + + +genunix`rwst_enter_common (28 samples, 0.05%) + + + +genunix`openat (49,647 samples, 86.43%) +genunix`openat + + +unix`mutex_enter (303 samples, 0.53%) + + + +lofs`lfind (278 samples, 0.48%) + + + +unix`mutex_exit (90 samples, 0.16%) + + + +genunix`cv_init (49 samples, 0.09%) + + + +unix`tsc_gethrtimeunscaled (43 samples, 0.07%) + + + +genunix`rwst_tryenter (32 samples, 0.06%) + + + +genunix`pn_fixslash (14 samples, 0.02%) + + + +genunix`gethrtime_unscaled (420 samples, 0.73%) + + + +genunix`post_syscall (4,245 samples, 7.39%) +genunix`po.. + + +genunix`kmem_zalloc (280 samples, 0.49%) + + + +genunix`vn_alloc (20 samples, 0.03%) + + + +genunix`vn_mountedvfs (43 samples, 0.07%) + + + +genunix`audit_getstate (15 samples, 0.03%) + + + +zfs`zfs_lookup (22 samples, 0.04%) + + + +genunix`crgetuid (6 samples, 0.01%) + + + +unix`copystr (598 samples, 1.04%) + + + +unix`i_ddi_splhigh (23 samples, 0.04%) + + + +unix`trap (13 samples, 0.02%) + + + +genunix`audit_getstate (27 samples, 0.05%) + + + +genunix`vn_mountedvfs (56 samples, 0.10%) + + + +unix`mutex_destroy (17 samples, 0.03%) + + + +genunix`cv_broadcast (14 samples, 0.02%) + + + +genunix`segvn_fault (11 samples, 0.02%) + + + +genunix`vn_rele (39 samples, 0.07%) + + + +genunix`kmem_free (457 samples, 0.80%) + + + +genunix`vn_vfsunlock (20 samples, 0.03%) + + + +genunix`vn_vfslocks_rele (34 samples, 0.06%) + + + +unix`atomic_cas_64 (318 samples, 0.55%) + + + +unix`mutex_enter (337 samples, 0.59%) + + + +unix`do_splx (31 samples, 0.05%) + + + +genunix`ufalloc_file (20 samples, 0.03%) + + + +genunix`fd_reserve (35 samples, 0.06%) + + + +genunix`copen (49,444 samples, 86.08%) +genunix`copen + + +unix`mutex_enter (279 samples, 0.49%) + + + +unix`0xfffffffffb800c91 (4,361 samples, 7.59%) +unix`0xfff.. + + +genunix`crgetmapped (55 samples, 0.10%) + + + +genunix`cv_init (56 samples, 0.10%) + + + +genunix`dnlc_lookup (26 samples, 0.05%) + + + +genunix`kmem_alloc (11 samples, 0.02%) + + + +genunix`cv_init (53 samples, 0.09%) + + + +unix`copyinstr (25 samples, 0.04%) + + + +genunix`gethrtime_unscaled (203 samples, 0.35%) + + + +genunix`kmem_cache_alloc (11 samples, 0.02%) + + + +genunix`vn_free (26 samples, 0.05%) + + + +unix`mutex_exit (149 samples, 0.26%) + + + +genunix`vn_recycle (319 samples, 0.56%) + + + +genunix`vn_rele (64 samples, 0.11%) + + + +unix`bcmp (11 samples, 0.02%) + + + +genunix`kmem_cache_free (154 samples, 0.27%) + + + +unix`lock_clear_splx (28 samples, 0.05%) + + + +genunix`unfalloc (729 samples, 1.27%) + + + +genunix`fop_lookup (85 samples, 0.15%) + + + +zfs`specvp_check (10 samples, 0.02%) + + + +genunix`lookupnameatcred (22 samples, 0.04%) + + + +unix`tsc_read (367 samples, 0.64%) + + + +genunix`memcmp (38 samples, 0.07%) + + + +unix`splx (6 samples, 0.01%) + + + +unix`mutex_exit (95 samples, 0.17%) + + + +genunix`gethrtime_unscaled (7 samples, 0.01%) + + + +genunix`rwst_init (13 samples, 0.02%) + + + +genunix`audit_getstate (31 samples, 0.05%) + + + +genunix`kmem_cache_alloc (32 samples, 0.06%) + + + +genunix`disp_lock_exit (2,096 samples, 3.65%) +genu.. + + +unix`mutex_exit (49 samples, 0.09%) + + + +unix`copyinstr (18 samples, 0.03%) + + + +ufs`ufs_lookup (46 samples, 0.08%) + + + +genunix`clear_stale_fd (10 samples, 0.02%) + + + +genunix`rwst_destroy (296 samples, 0.52%) + + + +genunix`syscall_mstate (1,336 samples, 2.33%) +g.. + + +genunix`kmem_alloc (934 samples, 1.63%) + + + +unix`atomic_add_32 (325 samples, 0.57%) + + + +unix`mutex_enter (947 samples, 1.65%) + + + +unix`mutex_exit (56 samples, 0.10%) + + + +unix`mutex_enter (318 samples, 0.55%) + + + +lofs`lo_root (80 samples, 0.14%) + + + +genunix`lookuppnvp (44,242 samples, 77.02%) +genunix`lookuppnvp + + +genunix`lookupnameat (46,075 samples, 80.21%) +genunix`lookupnameat + + +unix`setbackdq (5 samples, 0.01%) + + + +lofs`lo_root (31 samples, 0.05%) + + + +genunix`kmem_cache_alloc (17 samples, 0.03%) + + + +unix`mutex_exit (212 samples, 0.37%) + + + +genunix`vn_vfsrlock (2,414 samples, 4.20%) +genun.. + + +genunix`vfs_matchops (28 samples, 0.05%) + + + +unix`prunstop (36 samples, 0.06%) + + + +unix`mutex_exit (155 samples, 0.27%) + + + +unix`mutex_init (31 samples, 0.05%) + + + +unix`atomic_add_32_nv (100 samples, 0.17%) + + + +genunix`lookupnameat (69 samples, 0.12%) + + + +unix`_sys_rtt (6 samples, 0.01%) + + + +genunix`kmem_cache_alloc (49 samples, 0.09%) + + + +unix`tsc_gethrtimeunscaled (17 samples, 0.03%) + + + +genunix`fop_lookup (29,216 samples, 50.86%) +genunix`fop_lookup + + +unix`mutex_exit (142 samples, 0.25%) + + + +genunix`crgetmapped (31 samples, 0.05%) + + + +unix`do_splx (1,993 samples, 3.47%) +uni.. + + +genunix`kmem_cache_free (22 samples, 0.04%) + + + +unix`mutex_enter (95 samples, 0.17%) + + + +genunix`crhold (11 samples, 0.02%) + + + +unix`mutex_enter (823 samples, 1.43%) + + + +unix`mutex_exit (29 samples, 0.05%) + + + +genunix`vn_vfsrlock (3,342 samples, 5.82%) +genunix.. + + +unix`tsc_gethrtimeunscaled (13 samples, 0.02%) + + + +genunix`vn_rele (73 samples, 0.13%) + + + +unix`mutex_exit (337 samples, 0.59%) + + + +genunix`vn_vfslocks_getlock (973 samples, 1.69%) + + + +zfs`specvp_check (20 samples, 0.03%) + + + +genunix`vsd_free (14 samples, 0.02%) + + + +unix`mutex_enter (314 samples, 0.55%) + + + +genunix`cv_destroy (81 samples, 0.14%) + + + +genunix`cv_broadcast (25 samples, 0.04%) + + + +unix`mutex_enter (122 samples, 0.21%) + + + +unix`mutex_exit (55 samples, 0.10%) + + + +genunix`set_errno (24 samples, 0.04%) + + + +genunix`cv_destroy (42 samples, 0.07%) + + + +genunix`fd_find (13 samples, 0.02%) + + + +genunix`vn_invalid (47 samples, 0.08%) + + + +genunix`vfs_matchops (336 samples, 0.58%) + + + +unix`tsc_gethrtimeunscaled (59 samples, 0.10%) + + + +genunix`fop_inactive (39 samples, 0.07%) + + + +genunix`kmem_free (693 samples, 1.21%) + + + +genunix`syscall_mstate (412 samples, 0.72%) + + + +genunix`thread_lock (670 samples, 1.17%) + + + +lofs`lsave (162 samples, 0.28%) + + + +unix`atomic_add_64 (95 samples, 0.17%) + + + +genunix`audit_getstate (66 samples, 0.11%) + + + +genunix`dnlc_lookup (70 samples, 0.12%) + + + +genunix`vn_mountedvfs (30 samples, 0.05%) + + + +genunix`cv_broadcast (19 samples, 0.03%) + + + +genunix`kmem_alloc (533 samples, 0.93%) + + + +unix`mutex_exit (160 samples, 0.28%) + + + +genunix`memcmp (38 samples, 0.07%) + + + +unix`strlen (1,238 samples, 2.16%) +u.. + + +genunix`lookuppnatcred (12 samples, 0.02%) + + + +genunix`crfree (13 samples, 0.02%) + + + +lofs`table_lock_enter (43 samples, 0.07%) + + + +genunix`rwst_exit (18 samples, 0.03%) + + + +genunix`cv_destroy (31 samples, 0.05%) + + + +genunix`rwst_init (236 samples, 0.41%) + + + +genunix`vn_vfslocks_rele (1,420 samples, 2.47%) +ge.. + + +genunix`falloc (36 samples, 0.06%) + + + +genunix`setf (187 samples, 0.33%) + + + +zfs`zfs_fastaccesschk_execute (50 samples, 0.09%) + + + +genunix`vn_vfslocks_getlock (120 samples, 0.21%) + + + +genunix`fd_reserve (9 samples, 0.02%) + + + +genunix`vn_setops (160 samples, 0.28%) + + + +unix`sys_syscall (51,908 samples, 90.37%) +unix`sys_syscall + + +genunix`kmem_free (115 samples, 0.20%) + + + +genunix`vsd_free (48 samples, 0.08%) + + + +genunix`rexit (5 samples, 0.01%) + + + +genunix`vn_mountedvfs (11 samples, 0.02%) + + + +genunix`lookuppnatcred (44,681 samples, 77.79%) +genunix`lookuppnatcred + + +unix`splr (92 samples, 0.16%) + + + +genunix`vn_vfsrlock (13 samples, 0.02%) + + + +unix`mutex_exit (371 samples, 0.65%) + + + +genunix`kmem_cache_free (5 samples, 0.01%) + + + +genunix`dnlc_lookup (263 samples, 0.46%) + + + +genunix`audit_unfalloc (32 samples, 0.06%) + + + +unix`0xfffffffffb8001d6 (13 samples, 0.02%) + + + +genunix`rwst_destroy (146 samples, 0.25%) + + + +genunix`gethrtime_unscaled (182 samples, 0.32%) + + + +unix`mutex_enter (575 samples, 1.00%) + + + +unix`mutex_exit (148 samples, 0.26%) + + + +genunix`ufalloc_file (294 samples, 0.51%) + + + +unix`mutex_exit (163 samples, 0.28%) + + + +unix`membar_consumer (106 samples, 0.18%) + + + +genunix`crgetmapped (36 samples, 0.06%) + + + +genunix`memcmp (277 samples, 0.48%) + + + +genunix`cv_destroy (77 samples, 0.13%) + + + +genunix`kmem_cache_free (116 samples, 0.20%) + + + +genunix`kmem_cache_alloc (29 samples, 0.05%) + + + +genunix`fd_reserve (8 samples, 0.01%) + + + +zfs`zfs_lookup (946 samples, 1.65%) + + + +genunix`kmem_alloc (795 samples, 1.38%) + + + +unix`tsc_gethrtimeunscaled (11 samples, 0.02%) + + + +genunix`segvn_faultpage (7 samples, 0.01%) + + + +genunix`set_errno (9 samples, 0.02%) + + + +unix`splr (400 samples, 0.70%) + + + +genunix`rwst_destroy (32 samples, 0.06%) + + + +genunix`rwst_init (28 samples, 0.05%) + + + +unix`atomic_add_32 (292 samples, 0.51%) + + + +unix`0xfffffffffb800ca0 (517 samples, 0.90%) + + + +genunix`syscall_mstate (89 samples, 0.15%) + + + +genunix`kmem_alloc (73 samples, 0.13%) + + + +genunix`vn_vfsunlock (40 samples, 0.07%) + + + +unix`mutex_enter (1,202 samples, 2.09%) +u.. + + +lofs`makelfsnode (28 samples, 0.05%) + + + +unix`0xfffffffffb800c86 (472 samples, 0.82%) + + + +genunix`vn_rele (6,943 samples, 12.09%) +genunix`vn_rele + + +unix`mutex_exit (56 samples, 0.10%) + + + +genunix`kmem_cache_free (51 samples, 0.09%) + + + +genunix`gethrtime_unscaled (11 samples, 0.02%) + + + +unix`pagefault (13 samples, 0.02%) + + + +genunix`secpolicy_vnode_access2 (217 samples, 0.38%) + + + +genunix`vn_vfslocks_getlock (1,357 samples, 2.36%) +g.. + + +unix`bcmp (295 samples, 0.51%) + + + +unix`mutex_enter (97 samples, 0.17%) + + + +unix`membar_consumer (123 samples, 0.21%) + + + +genunix`audit_getstate (16 samples, 0.03%) + + + +unix`mutex_enter (455 samples, 0.79%) + + + +lofs`makelonode (4,212 samples, 7.33%) +lofs`makel.. + + +genunix`kmem_cache_alloc (168 samples, 0.29%) + + + +genunix`vn_vfslocks_getlock (62 samples, 0.11%) + + + +genunix`secpolicy_vnode_access2 (72 samples, 0.13%) + + + +genunix`kmem_cache_free (73 samples, 0.13%) + + + +genunix`vn_reinit (424 samples, 0.74%) + + + +genunix`pn_getcomponent (454 samples, 0.79%) + + + +genunix`fsop_root (297 samples, 0.52%) + + + +genunix`crgetuid (30 samples, 0.05%) + + + +genunix`kmem_free (785 samples, 1.37%) + + + +unix`mutex_exit (171 samples, 0.30%) + + + +genunix`crgetmapped (58 samples, 0.10%) + + + +unix`mutex_enter (299 samples, 0.52%) + + + +genunix`rwst_exit (167 samples, 0.29%) + + + +genunix`audit_falloc (8 samples, 0.01%) + + + +genunix`rwst_exit (110 samples, 0.19%) + + + +genunix`exit (5 samples, 0.01%) + + + +unix`mutex_exit (250 samples, 0.44%) + + + +lofs`freelonode (35 samples, 0.06%) + + + +genunix`rwst_tryenter (37 samples, 0.06%) + + + +ufs`ufs_iaccess (91 samples, 0.16%) + + + +unix`tsc_gethrtimeunscaled (12 samples, 0.02%) + + + +genunix`kmem_cache_alloc (241 samples, 0.42%) + + + +FSS`fss_preempt (8 samples, 0.01%) + + + +genunix`fd_reserve (15 samples, 0.03%) + + + +genunix`cv_broadcast (16 samples, 0.03%) + + + +genunix`crgetmapped (57 samples, 0.10%) + + + +unix`mutex_exit (379 samples, 0.66%) + + + +unix`mutex_destroy (31 samples, 0.05%) + + + +lofs`table_lock_enter (189 samples, 0.33%) + + + +genunix`rwst_enter_common (264 samples, 0.46%) + + + +genunix`kmem_free (11 samples, 0.02%) + + + +unix`atomic_add_32 (134 samples, 0.23%) + + + +genunix`ufalloc (551 samples, 0.96%) + + + +genunix`audit_falloc (313 samples, 0.54%) + + + +lofs`lo_lookup (19,887 samples, 34.62%) +lofs`lo_lookup + + +unix`atomic_add_64 (110 samples, 0.19%) + + + +genunix`vn_vfsunlock (2,372 samples, 4.13%) +genu.. + + +genunix`openat (17 samples, 0.03%) + + + +unix`bcmp (45 samples, 0.08%) + + + +genunix`audit_getstate (62 samples, 0.11%) + + + +genunix`crfree (9 samples, 0.02%) + + + +genunix`kmem_cache_free (18 samples, 0.03%) + + + +genunix`vn_vfslocks_rele (903 samples, 1.57%) + + + +genunix`vn_invalid (20 samples, 0.03%) + + + +genunix`vn_vfslocks_rele (50 samples, 0.09%) + + + +genunix`lookuppnvp (10 samples, 0.02%) + + + +genunix`fd_find (161 samples, 0.28%) + + + +ufs`ufs_lookup (5,399 samples, 9.40%) +ufs`ufs_lookup + + +unix`0xfffffffffb800c7c (42 samples, 0.07%) + + + +genunix`vn_openat (14 samples, 0.02%) + + + +genunix`setf (16 samples, 0.03%) + + + +genunix`traverse (7,243 samples, 12.61%) +genunix`traverse + + +genunix`rwst_tryenter (734 samples, 1.28%) + + + +unix`mutex_enter (366 samples, 0.64%) + + + +genunix`fop_lookup (6,470 samples, 11.26%) +genunix`fop_lookup + + +unix`mutex_exit (135 samples, 0.24%) + + + +lofs`makelfsnode (82 samples, 0.14%) + + + +genunix`copen (7 samples, 0.01%) + + + diff --git a/source/development/how-tos/images/queue_behaviour.png b/source/development/how-tos/images/queue_behaviour.png new file mode 100755 index 00000000..19ef4669 Binary files /dev/null and b/source/development/how-tos/images/queue_behaviour.png differ