Addr2line

It’s a way to identify where the bug happens, because I can run into a CallTrace without more informations, look like this:

[  139.288739] ------------[ cut here ]------------
[  139.288779] WARNING: CPU: 52 PID: 13556 at fs/iomap.c:66
iomap_seek_data+0xd0/0x240
[  139.288814] Modules linked in: pptp gre pppoe pppox ppp_generic slhc can_bcm
rfcomm bluetooth rfkill af_key ieee802154_socket ieee802154 atm can_raw can
binfmt_misc ipt_REJECT nf_reject_ipv4 xt_conntrack ip_set nfnetlink ebtable_nat
ebtable_broute bridge stp llc iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4
nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw
ebtable_filter ebtables ip6_tables iptable_filter i2c_dev nvidiafb sg at24
ofpart nvmem_core shpchp powernv_flash ipmi_powernv ipmi_devintf ipmi_msghandler
i2c_opal mtd uio_pdrv_genirq uio ibmpowernv opal_prd ip_tables xfs libcrc32c
sd_mod nouveau ast i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt
fb_sys_fops ttm ahci drm libahci libata tg3 ptp pps_core i2c_core dm_mirror
dm_region_hash dm_log dm_mod
[  139.289139] CPU: 52 PID: 13556 Comm: trinity-c5 Not tainted
4.11.0-44.el7a.ppc64le #1
[  139.289174] task: c000003f77426800 task.stack: c000003f76314000
[  139.289204] NIP: c0000000004d4890 LR: c0000000004d486c CTR: c0000000001b4ca0
[  139.289238] REGS: c000003f76317a80 TRAP: 0700   Not tainted
(4.11.0-44.el7a.ppc64le)
[  139.289272] MSR: 9000000000029033 <SF,HV,EE,ME,IR,DR,RI,LE>
[  139.289277]   CR: 24004424  XER: 20040000
[  139.289317] CFAR: c0080000382ee0dc SOFTE: 1 
[  139.289317] GPR00: c0000000004d486c c000003f76317d00 c000000001403100
0000000000000000 
[  139.289317] GPR04: c008000038379628 c000003f76317c8d c000003f76317c8c
00000000036c8200 
[  139.289317] GPR08: 0006d9042fef1c00 0003f76317cc0000 0000000000000001
c008000038342fe0 
[  139.289317] GPR12: 0000000000004000 c000000007afee00 0000000000000000
00000000100344b0 
[  139.289317] GPR16: 0000000010034678 0000000000000000 0000000000000000
0000000012329ba0 
[  139.289317] GPR20: 0000000010034518 0000000010034100 000000001001c490
c008000038356120 
[  139.289317] GPR24: 0000000000000000 c000003fc5fc2d58 00000000109857e8
0000000000000000 
[  139.289317] GPR28: fffffffffffffff7 0000000000000009 0000000000000000
0000000000000000 
[  139.289664] NIP [c0000000004d4890] iomap_seek_data+0xd0/0x240
[  139.289694] LR [c0000000004d486c] iomap_seek_data+0xac/0x240
[  139.289739] Call Trace:
[  139.289761] [c000003f76317d00] [c0000000004d486c] iomap_seek_data+0xac/0x240
(unreliable)
[  139.289827] [c000003f76317da0] [c0080000382df2c4] xfs_file_llseek+0x114/0x130
[xfs]
[  139.289864] [c000003f76317de0] [c00000000041a9a8] SyS_lseek+0xf8/0x130
[  139.289895] [c000003f76317e30] [c00000000000b004] system_call+0x38/0xe0
[  139.289923] Instruction dump:
[  139.289941] f8410018 7d2c4b78 4e800421 e8410018 2fa30000 7c7e1b78 7c7f1b78
409e0144 
[  139.289978] e9210028 7fa9e000 7d501026 554af7fe <0b0a0000> 2faa0000 40de0160
e9010030 
[  139.290015] ---[ end trace 451b8a13e0f6d488 ]---

Hey dude! What’s happened? …Let’s start the game.

Usage

$ addr2line -fip IMAGE_DBS MEMORY_ADDRESS
  • MEMORY_ADDRESS, so look carefully that address which was called NIP: c0000000004d4890 LR:c0000000004d486c CTR: c0000000001b4ca0
  • What is the IMAGE_DBS? it’s the kernel image compiled with debug symbols for be read by the addr2line then identifies which line of code is came from those address.

What are they, NIP, LR[2] and CTR[3]?

  • NIP(Next insctrution pointer) : Where the next instruction is allocated.
  • LR(Link Register): The link register can be thought of as the old instruction pointer for our purposes.
  • CTR(Count Register): The count register (called CTR) is a special-purpose register designed to hold loop counters.
$ addr2line -fip -e usr/lib/debug/lib/modules/4.11.0-44.el7a.ppc64le/vmlinux
c0000000004d4890
iomap_apply at /usr/src/debug/kernel-alt-4.11.0-44.el7a/linux-4.11.0-44.el7a.ppc64le/fs/iomap.c:66
 (inlined by) iomap_seek_data at /usr/src/debug/kernel-alt-4.11.0-44.el7a/linux-4.11.0-44.el7a.ppc64le/fs/iomap.c:670

After found the line of code, look in it:

$ vim kernel_src/linux-4.11.0-44.el7a/fs/iomap.c +670 # Using +N you go directly to line N.
...
 658 loff_t
 659 iomap_seek_data(struct inode *inode, loff_t offset, const struct iomap_ops
*ops)
 660 {
 661         loff_t size = i_size_read(inode);
 662         loff_t length = size - offset;
 663         loff_t ret;
 664 
 665         /* Nothing to be found beyond the end of the file. */
 666         if (offset >= size)
 667                 return -ENXIO;
 668 
 669         while (length > 0) {
 670                 ret = iomap_apply(inode, offset, length, IOMAP_REPORT, ops,
 671                                   &offset, iomap_seek_data_actor);
 672                 if (ret < 0)
 673                         return ret;
 674                 if (ret == 0)
 675                         break;
 676 
 677                 offset += ret;
 678                 length -= ret;
 679         }
 680 
 681         if (length <= 0)
 682                 return -ENXIO;
 683         return offset;
 684 }
 685 EXPORT_SYMBOL_GPL(iomap_seek_data);
 686 
...

Looking at iomap.c to see iomap_apply

  44 loff_t
  45 iomap_apply(struct inode *inode, loff_t pos, loff_t length, unsigned flags,
  46                 const struct iomap_ops *ops, void *data, iomap_actor_t
actor)
  47 {
  48         struct iomap iomap = { 0 };
  49         loff_t written = 0, ret;
  50 
  51         /*
  52          * Need to map a range from start position for length bytes. This
can
  53          * span multiple pages - it is only guaranteed to return a range of
a
  54          * single type of pages (e.g. all into a hole, all mapped or all
  55          * unwritten). Failure at this point has nothing to undo.
  56          *
  57          * If allocation is required for this range, reserve the space now
so
  58          * that the allocation is guaranteed to succeed later on. Once we
copy
  59          * the data into the page cache pages, then we cannot fail
otherwise we
  60          * expose transient stale data. If the reserve fails, we can safely
  61          * back out at this point as there is nothing to undo.
  62          */
  63         ret = ops->iomap_begin(inode, pos, length, flags, &iomap);
  64         if (ret)
  65                 return ret;
  66         if (WARN_ON(iomap.offset > pos))
  67                 return -EIO;
  68

So, we discovered that iomap_apply function is called by iomap_seek_data function in iomap.c:670, so we need to understand what is wrong in this point iomap.offset > pos to claim a WARN_ON.

References