kernel 系列之ktime_get()和ktime_sub()快速统计函数耗时

    关于这个标题，想着就当笔记记录一下调试过程吧，这个就简单整理一下了。在调试Xilinx XDMA的PCIE数据通讯传输时，测试发现在read buffer的时候耗时是相对比较长的，但也没有找出原因究竟耗时是在哪个位置。kernel中有个比较好用的函数就是ktime_get(),可以有助我们快速定位到那块引起的耗时较长。

在进入主题前，可以先参考一下这位大佬的博客关于Xilinx XDMA 数据传输sgdma 驱动代码分析：

Xilinx XDMA 数据传输sgdma 驱动代码分析-优快云博客

      简单理解为在无论用户层在read/write 文件设备的时候，Xilinx XDMA 均最终两个接口调用同一个接口char_sgdma_read_write（）进行数据输出， 接口以一个bool变量驱动，数据是读还是写

static ssize_t char_sgdma_read_write(struct file *file, const char __user *buf,
        size_t count, loff_t *pos, bool write)；

在debug的过程，在read buffer的时候，耗时是比较长的，关于该函数参考上面大佬的分析即可，这里主要说说ktime_get()的函数使用。

直接show：

diff --git a/nvidia/drivers/optcamera_xdma/libxdma.c b/nvidia/drivers/optcamera_xdma/libxdma.c
index f629425ce..16e3e3cc8 100755
--- a/nvidia/drivers/optcamera_xdma/libxdma.c
+++ b/nvidia/drivers/optcamera_xdma/libxdma.c
@@ -34,6 +34,9 @@
 #include "init_pcie.h"
 #include <linux/wait.h>
 
+#include <linux/ktime.h>
+#include <linux/timekeeping.h>
+
 extern wait_queue_head_t  sgdma_wait;
 extern int sgdma_poll_flag;
 extern int sgdma_int_flag;
@@ -3287,7 +3290,13 @@ ssize_t xdma_xfer_submit(void *dev_hndl, int channel, bool write, u64 ep_addr,
        enum dma_data_direction dir = write ? DMA_TO_DEVICE : DMA_FROM_DEVICE;
        struct xdma_request_cb *req = NULL;
 
         printk("%s xdma_xfer start...\n",__func__);
+        //add by tab to debug stransxfer time
+        ktime_t curTime, curTime_submit, curTime_submit_gap;
+        unsigned long long submit_time;
+        curTime = ktime_get(); 

//获取基于CLOCK_MONOTONIC的当前时间，返回ktime_t格式的数据类型
+        //end by tab   

        printk("%s xdma_xfer start...\n",__func__);
        if (!dev_hndl)
                return -EINVAL;
 
@@ -3479,10 +3488,18 @@ ssize_t xdma_xfer_submit(void *dev_hndl, int channel, bool write, u64 ep_addr,
                        goto unmap_sgl;
                }
        } /* while (sg) */
        dbg_tfr("%s, xfer finish !!!\n", engine->name);
        printk("%s xdma_xfer finished !!!\n",__func__);
 
+        curTime_submit = ktime_get();

+      //ktime_sub计算其差值，就是这段代码运行消耗的时间，注意返回类型
+        curTime_submit_gap = ktime_sub(curTime_submit, curTime);
+        submit_time = (unsigned long long) ktime_to_ns(curTime_submit_gap) >> 10;//微秒
+        //submit_time = (unsigned long long)ktime_to_ms(curTime_submit_gap) >> 10;//毫秒
+        printk("[hezhensheng] %s after submit_time = %lld us \n", __func__, submit_time);
+        //printk("[hezhensheng] %s after submit_time = %lld ms \n", __func__, submit_time);
 

通过上面即可快速获取xdma_xfer_submit函数的运行时间，我打印的是us，有需要的话可以改为ms，两者区别ktime_to_ns()和ktime_to_ms()

通过串口的内核打印：

6,1030,78597138,-;ray gpio switch =1,gpiostat=0
6,1031,78598303,-;char_sgdma_llseek ...  whence = 0  off =2151677952
6,1032,78598311,-;char_sgdma_llseek ...  file->f_pos  =2151677952
6,1033,78598493,-;char_sgdma_read ...  pos = 2151677952
6,1034,78859053,-;char_sgdma_read_write file 0xffffffc1b8e40a00, priv 0xffffffc1f120c0e8, buf 0x0000007fada82060,90243072, pos 2151677952, W 0, 0-C2H0-MM.
6,1035,78875754,-;xdma_xfer_submit xdma_xfer start...
6,1036,78963657,-;xdma_xfer_submit xdma_xfer finished !!!
6,1037,78963668,-;[hezhensheng] xdma_xfer_submit after submit_time = 85856 us
6,1038,79092925,-;char_sgdma_llseek ...  whence = 0  off =2151677952
6,1039,79092933,-;char_sgdma_llseek ...  file->f_pos  =2151677952
6,1040,79092959,-;char_sgdma_read ...  pos = 2151677952
6,1041,79354546,-;char_sgdma_read_write file 0xffffffc1b8e40a00, priv 0xffffffc1f120c0e8, buf 0x0000007fada82060,90243072, pos 2151677952, W 0, 0-C2H0-MM.
6,1042,79355623,-;xdma_xfer_submit xdma_xfer start...
6,1043,79446109,-;xdma_xfer_submit xdma_xfer finished !!!
6,1044,79446179,-;[hezhensheng] xdma_xfer_submit after submit_time = 88435 us
6,1045,79482951,-;char_sgdma_llseek ...  whence = 0  off =2151677952
6,1046,79482959,-;char_sgdma_llseek ...  file->f_pos  =2151677952
6,1047,79482986,-;char_sgdma_read ...  pos = 2151677952
6,1048,79744536,-;char_sgdma_read_write file 0xffffffc1b8e40a00, priv 0xffffffc1f120c0e8, buf 0x0000007fada82060,90243072, pos 2151677952, W 0, 0-C2H0-MM.
6,1049,79746224,-;xdma_xfer_submit xdma_xfer start...
6,1050,79835612,-;xdma_xfer_submit xdma_xfer finished !!!
6,1051,79835625,-;[hezhensheng] xdma_xfer_submit after submit_time = 87305 us
6,1052,79871890,-;enter opt_ide1_do_release\x0d
6,1053,79871901,-;char_sgdma_close ...

详情可查阅内核

include$ vim linux/timekeeping.h

/*
 * ktime_get() family: read the current time in a multitude of ways,
 *
 * The default time reference is CLOCK_MONOTONIC, starting at
 * boot time but not counting the time spent in suspend.
 * For other references, use the functions with "real", "clocktai",
 * "boottime" and "raw" suffixes.
 *
 * To get the time in a different format, use the ones wit
 * "ns", "ts64" and "seconds" suffix.
 *
 * See Documentation/core-api/timekeeping.rst for more details.
 */

 include$ vim linux/ktime.h

/* Subtract two ktime_t variables. rem = lhs -rhs: */
#define ktime_sub(lhs, rhs)     ((lhs) - (rhs))