内核调试工具ftrace

1、ftrace基本介绍

ftrace 的作用是帮助开发人员了解 Linux 内核的运行时行为，以便进行故障调试或性能分析。

最早 ftrace 是一个 function tracer，仅能够记录内核的函数调用流程。如今 ftrace 已经成为一个 framework，采用 plugin 的方式支持开发人员添加更多种类的 trace 功能。

2、基本用法

首先编译内核，使内核支持ftrace。

通过以上配置，使得内核支持ftrace。

完成内核编译之后，启动内核，在文件系统中挂载bebugfs。

mount -t debugfs none /debug

然后进入debug/tracing，就可以看到ftarce的一些文件。

这里暂不对这些文件进行解释，先通过示例演示基本用法。

2.1、实例演示

目的：分析bash如何读取串口输入的数据，如何进行回显。

1、先关闭ftrace的追踪，待设置完毕再打开。

echo 0 > tracing_on

2、找到当前控制台上运行的bash的pid，输入到文件set_ftrace_pid当中，具体操作如下：

首先通过ps找到sh的PID

echo 2036 > set_ftrace_pid

3、设置tracers、设置追踪深度

echo function_graph > current_tracer

echo 5 > max_graph_depth

4、通过telnet开启追踪并查看

echo 1 > tracing_on

cat trace_pipe

5、通过控制台输入1个字符，查看结果

 ------------------------------------------
 0)   rb_prod-31   =>    sh-2036    
 ------------------------------------------

 0) $ 21745966 us |          }
 0)   ==========> |
 0) + 31.069 us   |          gic_handle_irq();
 0)   0.814 us    |          tty_ldisc_deref();
 0)   0.488 us    |          get_seconds();
 0) $ 21746054 us |        }
 0) $ 21746058 us |      }
 0)   0.488 us    |      __fsnotify_parent();
 0)   0.488 us    |      fsnotify();
 0) $ 21746078 us |    }
 0) $ 21746094 us |  } //sysread
 0)               |  SyS_write() {
 0)               |    __fdget_pos() {
 0)               |      __fdget() {
 0)   0.976 us    |        __fget_light();
 0)   5.205 us    |      }
 0)   9.272 us    |    }
 0)               |    vfs_write() {
 0)   0.488 us    |      rw_verify_area();
 0)               |      __vfs_write() {
 0)               |        tty_write() {
 0)   0.326 us    |          tty_paranoia_check();
 0)   0.814 us    |          tty_ldisc_ref_wait();
 0)   0.813 us    |          tty_write_lock();
 0) + 47.987 us   |          n_tty_write();
 0)   0.488 us    |          get_seconds();
 0)   3.416 us    |          tty_write_unlock();
 0)   0.813 us    |          tty_ldisc_deref();
 0) + 82.309 us   |        }
 0) + 86.051 us   |      }
 0)   0.326 us    |      __fsnotify_parent();
 0)   0.488 us    |      fsnotify();
 0) ! 102.643 us  |    }
 0) ! 119.722 us  |  }
 0)               |  SyS_read() {
 0)               |    __fdget_pos() {
 0)               |      __fdget() {
 0)   0.488 us    |        __fget_light();
 0)   4.554 us    |      }
 0)   8.459 us    |    }
 0)               |    vfs_read() {
 0)   0.488 us    |      rw_verify_area();
 0)               |      __vfs_read() {
 0)               |        tty_read() {
 0)   0.325 us    |          tty_paranoia_check();
 0)   ==========> |
 0) + 20.170 us   |          gic_handle_irq();
 0)   0.814 us    |          tty_ldisc_ref_wait();
 0)               |          n_tty_read() {

以上是一个深度为5的调用关系，截取SyS_write()部分进行分析。

 0)               |  SyS_write() {
 0)               |    __fdget_pos() {
 0)               |      __fdget() {
 0)   0.976 us    |        __fget_light();
 0)   5.205 us    |      }
 0)   9.272 us    |    }
 0)               |    vfs_write() {
 0)   0.488 us    |      rw_verify_area();
 0)               |      __vfs_write() {

以上部分可以很简单的分析出是系统的顶层的供应用使用的通用接口，通过设备号最终找到驱动当中的具体操作函数。所以暂不分析顶层的API接口，主要分析驱动中的代码。

 0)               |      __vfs_write() {
 0)               |        tty_write() {
 0)   0.326 us    |          tty_paranoia_check();
 0)   0.814 us    |          tty_ldisc_ref_wait();
 0)   0.813 us    |          tty_write_lock();
 0) + 47.987 us   |          n_tty_write();
 0)   0.488 us    |          get_seconds();
 0)   3.416 us    |          tty_write_unlock();
 0)   0.813 us    |          tty_ldisc_deref();
 0) + 82.309 us   |        }
 0) + 86.051 us   |      }

通过全局搜索tty_write，结合编译出的*.o文件，找到具体的操作函数。

static ssize_t tty_write(struct file *file, const char __user *buf,
						size_t count, loff_t *ppos)
{
	struct tty_struct *tty = file_tty(file);
 	struct tty_ldisc *ld;
	ssize_t ret;

	if (tty_paranoia_check(tty, file_inode(file), "tty_write"))//执行标记
		return -EIO;
	if (!tty || !tty->ops->write ||
		(test_bit(TTY_IO_ERROR, &tty->flags)))
			return -EIO;
	/* Short term debug to catch buggy drivers */
	if (tty->ops->write_room == NULL)
		printk(KERN_ERR "tty driver %s lacks a write_room method.\n",
			tty->driver->name);
	ld = tty_ldisc_ref_wait(tty);//执行标记，获取n_tty的操作函数
	if (!ld->ops->write)
		ret = -EIO;
	else
		ret = do_tty_write(ld->ops->write, tty, file, buf, count);//进入该函数,此处可以发现问题
	tty_ldisc_deref(ld);//执行标记
	return ret;
}

在do_tty_write当中可以发现问题，发现并未调用此函数，但是执行了此函数中的一系列函数，找到此函数之后，发现该函数是一个内联函数，直接被展开了，所以并未出现该函数的调用，而是直接运行了函数内的函数。

static inline ssize_t do_tty_write(
	ssize_t (*write)(struct tty_struct *, struct file *, const unsigned char *, size_t),
	struct tty_struct *tty,
	struct file *file,
	const char __user *buf,
	size_t count)
{
	ssize_t ret, written = 0;
	unsigned int chunk;

	ret = tty_write_lock(tty, file->f_flags & O_NDELAY);//执行标记
	if (ret < 0)
		return ret;
	chunk = 2048;
	if (test_bit(TTY_NO_WRITE_SPLIT, &tty->flags))
		chunk = 65536;
	if (count < chunk)
		chunk = count;
	/* write_buf/write_cnt is protected by the atomic_write_lock mutex */
	if (tty->write_cnt < chunk) {
		unsigned char *buf_chunk;
		if (chunk < 1024)
			chunk = 1024;
		buf_chunk = kmalloc(chunk, GFP_KERNEL);
		if (!buf_chunk) {
			ret = -ENOMEM;
			goto out;
		}
		kfree(tty->write_buf);
		tty->write_cnt = chunk;
		tty->write_buf = buf_chunk;
	}
	/* Do the write .. */
	for (;;) {
		size_t size = count;
		if (size > chunk)
			size = chunk;
		ret = -EFAULT;
		if (copy_from_user(tty->write_buf, buf, size))
			break;
		ret = write(tty, file, tty->write_buf, size);//执行标记，进入n_tty_write函数
		if (ret <= 0)
			break;
		written += ret;
		buf += ret;
		count -= ret;
		if (!count)
			break;
		ret = -ERESTARTSYS;
		if (signal_pending(current))
			break;
		cond_resched();
	}
	if (written) {
		tty_update_time(&file_inode(file)->i_mtime);//执行标记
		ret = written;
	}
out:
	tty_write_unlock(tty);//执行标记
	return ret;
}

由以上代码可知，最终调用了n_tty_write函数，下面深入到该函数进行分析。

static ssize_t n_tty_write(struct tty_struct *tty, struct file *file,
			   const unsigned char *buf, size_t nr)
{
	const unsigned char *b = buf;
	DEFINE_WAIT_FUNC(wait, woken_wake_function);
	int c;
	ssize_t retval = 0;

	/* Job control check -- must be done at start (POSIX.1 7.1.1.4). */
	if (L_TOSTOP(tty) && file->f_op->write != redirected_tty_write) {
		retval = tty_check_change(tty);
		if (retval)
			return retval;
	}

	down_read(&tty->termios_rwsem);//执行标记

	/* Write out any echoed characters that are still pending */
	process_echoes(tty);//执行标记

	add_wait_queue(&tty->write_wait, &wait);//执行标记
	while (1) {
		if (signal_pending(current)) {
			retval = -ERESTARTSYS;
			break;
		}
		if (tty_hung_up_p(file) || (tty->link && !tty->link->count)) {//执行标记
			retval = -EIO;
			break;
		}
		if (O_OPOST(tty)) {
			while (nr > 0) {
				ssize_t num = process_output_block(tty, b, nr);//执行标记
				if (num < 0) {
					if (num == -EAGAIN)
						break;
					retval = num;
					goto break_out;
				}
				b += num;
				nr -= num;
				if (nr == 0)
					break;
				c = *b;
				if (process_output(c, tty) < 0)
					break;
				b++; nr--;
			}
			if (tty->ops->flush_chars)
				tty->ops->flush_chars(tty);//执行标记
		} else···
break_out:
	remove_wait_queue(&tty->write_wait, &wait);//执行标记
	if (b - buf != nr && tty->fasync)
		set_bit(TTY_DO_WRITE_WAKEUP, &tty->flags);
	up_read(&tty->termios_rwsem);//执行标记
	return (b - buf) ? b - buf : retval;
}

以上代码未进行ftrace追踪，所以暂时不知道具体的执行情况，下面增加ftrace的追踪深度，进一步研究程序如何运行。

 1)               |          n_tty_write() {
 1)   0.488 us    |            down_read();
 1)   0.326 us    |            process_echoes();
 1)               |            add_wait_queue() {
 1)   1.464 us    |              _raw_spin_lock_irqsave();
 1)   1.139 us    |              _raw_spin_unlock_irqrestore();
 1)   9.923 us    |            }
 1)   0.488 us    |            tty_hung_up_p();
 1)   0.488 us    |            mutex_lock();
 1)               |            tty_write_room() {
 1)   3.091 us    |              uart_write_room();
 1)   7.157 us    |            }
 1)               |            uart_write() {
 1)   1.464 us    |              _raw_spin_lock_irqsave();
 1)   5.856 us    |              __uart_start();
 1)   1.138 us    |              _raw_spin_unlock_irqrestore();
 1) + 18.869 us   |            }
 1)   0.488 us    |            mutex_unlock();
 1)               |            uart_flush_chars() {
 1)   6.344 us    |              uart_start();
 1) + 10.574 us   |            }
 1)               |            remove_wait_queue() {
 1)   1.301 us    |              _raw_spin_lock_irqsave();
 1)   1.139 us    |              _raw_spin_unlock_irqrestore();
 1)   9.435 us    |            }
 1)   0.326 us    |            up_read();
 1) ! 101.179 us  |          }

static ssize_t process_output_block(struct tty_struct *tty,
				    const unsigned char *buf, unsigned int nr)
{
	struct n_tty_data *ldata = tty->disc_data;
	int	space;
	int	i;
	const unsigned char *cp;

	mutex_lock(&ldata->output_lock);//执行标记

	space = tty_write_room(tty);//执行标记
	if (!space) {
		mutex_unlock(&ldata->output_lock);
		return 0;
	}
	if (nr > space)
		nr = space;

	for (i = 0, cp = buf; i < nr; i++, cp++) {
		unsigned char c = *cp;

		switch (c) {
		case '\n':
			if (O_ONLRET(tty))
				ldata->column = 0;
			if (O_ONLCR(tty))
				goto break_out;
			ldata->canon_column = ldata->column;
			break;
		case '\r':
			if (O_ONOCR(tty) && ldata->column == 0)
				goto break_out;
			if (O_OCRNL(tty))
				goto break_out;
			ldata->canon_column = ldata->column = 0;
			break;
		case '\t':
			goto break_out;
		case '\b':
			if (ldata->column > 0)
				ldata->column--;
			break;
		default:
			if (!iscntrl(c)) {
				if (O_OLCUC(tty))
					goto break_out;
				if (!is_continuation(c, tty))
					ldata->column++;
			}
			break;
		}
	}
break_out:
	i = tty->ops->write(tty, buf, i);//执行标记，此处进入uart_write
	mutex_unlock(&ldata->output_lock);//执行标记
	return i;
}

至此已经追踪到了tty如何调用的串口发送，进一步研究就到了具体的串口发送函数。

 1)               |            uart_write() {
 1)               |              _raw_spin_lock_irqsave() {
 1)   0.650 us    |                preempt_count_add();
 1)   4.555 us    |              }
 1)               |              __uart_start() {
 1)               |                serial8250_start_tx() {
 1)               |                  __pm_runtime_resume() {
 1)               |                    _raw_spin_lock_irqsave() {
 1)   0.325 us    |                      preempt_count_add();
 1)   3.742 us    |                    }
 1)               |                    rpm_resume() {
 1)   0.488 us    |                      pm_runtime_deactivate_timer();
 1)   3.741 us    |                    }
 1)               |                    _raw_spin_unlock_irqrestore() {
 1)   0.325 us    |                      preempt_count_sub();
 1)   3.741 us    |                    }
 1) + 20.008 us   |                  }
 1)               |                  omap_8250_tx_dma() {
 1)   0.814 us    |                    mem_serial_in();
 1)   4.392 us    |                  }
 1)               |                  mem_serial_out() {
 1)               |                    arm_heavy_mb() {
 1)   0.488 us    |                      omap4_mb();
 1)   3.904 us    |                    }
 1)   6.995 us    |                  }
 1) + 40.667 us   |                }
 1) + 43.757 us   |              }
 1)               |              _raw_spin_unlock_irqrestore() {
 1)   0.650 us    |                preempt_count_sub();
 1)   4.880 us    |              }
 1) + 63.277 us   |

继续对串口写函数进行深层次的追踪，得到信息如上，可以看到serial8250_start_tx，以及omap_8250_tx_dma调用都已经打出来了。

下面对__uart_start函数进行研究。

static void __uart_start(struct tty_struct *tty)
{
	struct uart_state *state = tty->driver_data;
	struct uart_port *port = state->uart_port;

	if (!uart_tx_stopped(port))
		port->ops->start_tx(port);
}

可以看到，tty->driver_data当中有个uart_port变量，该变量就是serial8250驱动中的结构体，并运行了其中的操作函数start_tx。

static void serial8250_start_tx(struct uart_port *port)
{
	struct uart_8250_port *up = up_to_u8250p(port);

	serial8250_rpm_get_tx(up);

	if (up->dma && !up->dma->tx_dma(up))
		return;

	if (!(up->ier & UART_IER_THRI)) {
		up->ier |= UART_IER_THRI;
		serial_port_out(port, UART_IER, up->ier);

		if (up->bugs & UART_BUG_TXEN) {
			unsigned char lsr;
			lsr = serial_in(up, UART_LSR);
			up->lsr_saved_flags |= lsr & LSR_SAVE_FLAGS;
			if (lsr & UART_LSR_THRE)
				serial8250_tx_chars(up);
		}
	}
	if (port->type == PORT_16C950 && up->acr & UART_ACR_TXDIS) {
		up->acr &= ~UART_ACR_TXDIS;
		serial_icr_write(up, UART_ACR, up->acr);
	}
}

2.2、结构展示

上图展示了基本的调用流程。下图展示了整个结构体在内核中的传递情况。