[PATCH]: viewing TCE usage stats in /proc
linas at austin.ibm.com
linas at austin.ibm.com
Thu Nov 20 05:35:44 EST 2003
Hi,
Here is a half-finished patch I'm using to debug TCE allocation problems
on the ppc64 platform. TCE's are used to translate PCI DMA addresses,
and TCE table entries are heavily alloced/freed during scsi scatter-gather
DMA ops. This patch prints usage statistics for the tce table, and can
give you some idea of what a device driver is doing with all those dma
blcoks.
I'm trying to gauge interest in this patch... anyone out there find this
interesting? Anyone have feature requests? This patch is currently
for 2.4.21. Its only for ppc64 pSeries, since I don't think the ppc
processors use tce's in thier i/o subsystem. However, I'm surely not
the first to look at pci dma scatter-gather bugs, and so I thought this
topic might be of general interest. I'd like to submit the final patch
to the 2.6.0 tree at some point, unless everyone thinks this would be a
dumb idea.
The patch collects tce usage stats. These can be viewed either with
kdb, or with a /proc/ppc64/tce/stats entry. I'm working on putting
detailed stats into /proc/ppc64/tce/busid:devid files. (The patch is
half-finished, so, yes there is some crud in it).
--linas
-------------- next part --------------
Index: arch/ppc64/kdb/kdbasupport.c
===================================================================
RCS file: /cvs/local/sles8/arch/ppc64/kdb/kdbasupport.c,v
retrieving revision 1.1.1.2
diff -u -p -r1.1.1.2 kdbasupport.c
--- arch/ppc64/kdb/kdbasupport.c 10 Sep 2003 13:14:42 -0000 1.1.1.2
+++ arch/ppc64/kdb/kdbasupport.c 19 Nov 2003 18:02:12 -0000
@@ -1693,11 +1693,16 @@ kdba_dump_tce_table(int argc, const char
long tce_table_address;
int nr;
int i,j,k;
- int full,empty;
+ int full,partial,empty;
int fulldump=0;
u64 mapentry;
- int totalpages;
+ int freepages;
int levelpages;
+#ifdef CONFIG_TCE_STATS
+ struct tce_blk_stats *blk_stats;
+ int alloced_blocks, stale_blocks;
+ unsigned long alloc_jiffies;
+#endif /* CONFIG_TCE_STATS */
if (argc == 0) {
kdb_printf("need address\n");
@@ -1710,17 +1715,21 @@ kdba_dump_tce_table(int argc, const char
if (strcmp(argv[2], "full") == 0)
fulldump=1;
- /* with address, read contents of memory and dump tce table. */
- /* possibly making some assumptions on the depth and size of table..*/
+ /* use address to read contents of memory and dump tce table. */
- nr = kdba_readarea_size(tce_table_address+0 ,&kt.busNumber,8);
- nr = kdba_readarea_size(tce_table_address+8 ,&kt.size,8);
- nr = kdba_readarea_size(tce_table_address+16,&kt.startOffset,8);
- nr = kdba_readarea_size(tce_table_address+24,&kt.base,8);
- nr = kdba_readarea_size(tce_table_address+32,&kt.index,8);
- nr = kdba_readarea_size(tce_table_address+40,&kt.tceType,8);
+#define GET_TCE_VAL(X) \
+ nr = kdba_readarea_size( \
+ ((long) &(((struct TceTable *)tce_table_address)->X)), \
+ &(kt.X), sizeof(kt.X));
+
+ GET_TCE_VAL (busNumber);
+ GET_TCE_VAL (size);
+ GET_TCE_VAL (startOffset);
+ GET_TCE_VAL (base);
+ GET_TCE_VAL (index);
+ GET_TCE_VAL (tceType);
#ifdef CONFIG_SMP
- nr = kdba_readarea_size(tce_table_address+48,&kt.lock,8);
+ GET_TCE_VAL (lock);
#endif
kdb_printf("\n");
@@ -1734,43 +1743,90 @@ kdba_dump_tce_table(int argc, const char
#ifdef CONFIG_SMP
kdb_printf("lock: 0x%x \n",(uint)kt.lock.lock);
#endif
- nr = kdba_readarea_size(tce_table_address+56,&kt.mlbm.maxLevel,8);
- kdb_printf(" maxLevel: 0x%x \n",(uint)kt.mlbm.maxLevel);
- totalpages=0;
+ GET_TCE_VAL (mlbm.maxLevel);
+ kdb_printf(" maxLevel: 0x%x \n",(uint)kt.mlbm.maxLevel);
+#ifdef CONFIG_TCE_STATS
+ GET_TCE_VAL (use_cnt);
+ kdb_printf(" use_cnt: %d \n",(uint)kt.use_cnt);
+#endif
+ freepages=0;
for (i=0;i<NUM_TCE_LEVELS;i++) {
- nr = kdba_readarea_size(tce_table_address+64+i*24,&kt.mlbm.level[i].numBits,8);
- nr = kdba_readarea_size(tce_table_address+72+i*24,&kt.mlbm.level[i].numBytes,8);
- nr = kdba_readarea_size(tce_table_address+80+i*24,&kt.mlbm.level[i].map,8);
+ GET_TCE_VAL (mlbm.level[i].numBits);
+ GET_TCE_VAL (mlbm.level[i].numBytes);
+ GET_TCE_VAL (mlbm.level[i].map);
kdb_printf(" level[%d]\n",i);
kdb_printf(" numBits: 0x%x\n",(uint)kt.mlbm.level[i].numBits);
kdb_printf(" numBytes: 0x%x\n",(uint)kt.mlbm.level[i].numBytes);
kdb_printf(" map*: %p\n",kt.mlbm.level[i].map);
+#ifdef CONFIG_TCE_STATS
+ GET_TCE_VAL (mlbm.level[i].blk_stats);
+ blk_stats = kt.mlbm.level[i].blk_stats;
+ if (blk_stats) {
+ alloced_blocks = 0;
+ stale_blocks = 0;
+ /* alloc_jiffies will be set if the block is allocated and not freed.
+ * stale blocks suggest a leak or a really slow i/o system */
+ for (j=0; j<kt.mlbm.level[i].numBits; j++) {
+ kdba_readarea_size( (long) (&(blk_stats[j].alloc_jiffies)), &alloc_jiffies, 8);
+ if (alloc_jiffies && alloc_jiffies != ((unsigned long) -1)) {
+ alloced_blocks++;
+ /* 'stale' if alloc happened more than 3 seconds ago */
+ if (jiffies - alloc_jiffies > 3*HZ) {
+ stale_blocks ++;
+ }
+ }
+ }
+ kdb_printf(" blk_stats: %p\n", blk_stats);
+ } else {
+ alloced_blocks = -1;
+ stale_blocks = -1;
+ }
+ GET_TCE_VAL (mlbm.level[i].use_cnt);
+ GET_TCE_VAL (mlbm.level[i].split_cnt);
+ GET_TCE_VAL (mlbm.level[i].merge_cnt);
+ kdb_printf(" use_cnt: %d split: %d merge: %d alloced: %d stale: %d\n",
+ kt.mlbm.level[i].use_cnt,
+ kt.mlbm.level[i].split_cnt,
+ kt.mlbm.level[i].merge_cnt,
+ alloced_blocks,
+ stale_blocks);
+#endif
/* if these dont match, this might not be a valid tce table, so
dont try to iterate the map entries. */
if (kt.mlbm.level[i].numBits == 8*kt.mlbm.level[i].numBytes) {
- full=0;empty=0;levelpages=0;
+ int n=0;
+ full=0;partial=0;empty=0;levelpages=0;
for (j=0;j<kt.mlbm.level[i].numBytes; j++) {
mapentry=0;
nr = kdba_readarea_size((long int)(kt.mlbm.level[i].map+j),&mapentry,1);
- if (mapentry)
+ mapentry >>= 56;
+ if (mapentry == 0xff)
full++;
+ else if (mapentry)
+ partial++;
else
empty++;
if (mapentry && fulldump) {
- kdb_printf("0x%lx\n",mapentry);
+ if (n && (n%32 == 0)) kdb_printf ("\n");
+ kdb_printf("%02lx ",(int) mapentry);
+ n++;
}
- for (k=0;(k<=64) && ((0x1UL<<k) <= mapentry);k++) {
+ for (k=0;(k<8) && ((0x1UL<<k) <= mapentry);k++) {
if ((0x1UL<<k) & mapentry) levelpages++;
}
}
- kdb_printf(" full:0x%x empty:0x%x pages:0x%x\n",full,empty,levelpages);
+ if (fulldump) kdb_printf ("\n");
+ kdb_printf(" full:0x%x partial:0x%x empty:0x%x free:0x%x\n",
+ full,partial,empty,levelpages);
} else {
kdb_printf(" numBits/numBytes mismatch..? \n");
}
- totalpages+=levelpages;
+ freepages += (1UL<<i) * levelpages;
}
- kdb_printf(" Total pages:0x%x\n",totalpages);
+ kdb_printf(" Total pages: 0x%lx free:0x%x used:0x%lx\n",
+ kt.mlbm.level[0].numBits, freepages,
+ kt.mlbm.level[0].numBits - freepages);
kdb_printf("\n");
return 0;
}
Index: arch/ppc64/kernel/Makefile
===================================================================
RCS file: /cvs/local/sles8/arch/ppc64/kernel/Makefile,v
retrieving revision 1.1.1.7
diff -u -p -r1.1.1.7 Makefile
--- arch/ppc64/kernel/Makefile 29 Sep 2003 19:25:45 -0000 1.1.1.7
+++ arch/ppc64/kernel/Makefile 19 Nov 2003 18:02:12 -0000
@@ -29,7 +29,7 @@ obj-y := ppc_ksyms.o setup
iSeries_proc.o HvCall.o flight_recorder.o HvLpConfig.o \
rtc.o perfmon.o cputable.o vio.o
-obj-$(CONFIG_PCI) += pci.o pci_dn.o pci_dma.o pSeries_lpar.o pSeries_hvCall.o
+obj-$(CONFIG_PCI) += pci.o pci_dn.o pci_dma.o proc_tce.o pSeries_lpar.o pSeries_hvCall.o
ifeq ($(CONFIG_PPC_ISERIES),y)
obj-$(CONFIG_PCI) += iSeries_pci.o iSeries_pci_reset.o iSeries_IoMmTable.o iSeries_irq.o iSeries_VpdInfo.o XmPciLpEvent.o
Index: arch/ppc64/kernel/pci_dma.c
===================================================================
RCS file: /cvs/local/sles8/arch/ppc64/kernel/pci_dma.c,v
retrieving revision 1.1.1.4
diff -u -p -r1.1.1.4 pci_dma.c
--- arch/ppc64/kernel/pci_dma.c 2 Sep 2003 15:34:24 -0000 1.1.1.4
+++ arch/ppc64/kernel/pci_dma.c 19 Nov 2003 18:02:12 -0000
@@ -44,7 +44,7 @@
#include "pci.h"
/* #define DEBUG_TCE 1 */
-/* #define MONITOR_TCE 1 */ /* Turn on to sanity check TCE generation. */
+#define MONITOR_TCE 1 /* Turn on to sanity check TCE generation. */
/* Initialize so this guy does not end up in the BSS section.
@@ -212,6 +212,42 @@ static void tce_build_pSeries(struct Tce
}
+#ifdef CONFIG_TCE_STATS
+/*
+ * Initialize tce-table statistics. Handy typically only for device driver
+ * debugging, perf tuning, etc.
+ */
+void build_tce_stats(struct TceTable * tbl)
+{
+ int num_entries, num_bytes, i;
+ struct tce_blk_stats *p;
+
+ /* Alloc per-block stats array */
+ num_entries = tbl->mlbm.level[0].numBits;
+ num_entries *= 2; /* room for other levels as well */
+ num_bytes = num_entries * sizeof( struct tce_blk_stats );
+ p = (struct tce_blk_stats *)__get_free_pages( GFP_ATOMIC, get_order( num_bytes ));
+
+ /* alloc may fail for large areas; keep driving */
+ if (p) memset( p, 0, num_bytes );
+
+ for (i=0; i<NUM_TCE_LEVELS; ++i) {
+ tbl->mlbm.level[i].use_cnt = 0;
+ tbl->mlbm.level[i].split_cnt = 0;
+ tbl->mlbm.level[i].merge_cnt = 0;
+
+ if (p) {
+ tbl->mlbm.level[i].blk_stats = p;
+ p += tbl->mlbm.level[i].numBits;
+ } else {
+ tbl->mlbm.level[i].blk_stats = 0x0;
+ }
+ }
+
+ tbl->use_cnt = 0;
+}
+
+#endif /* CONFIG_TCE_STATS */
/*
* Build a TceTable structure. This contains a multi-level bit map which
* is used to manage allocation of the tce space.
@@ -276,7 +312,6 @@ struct TceTable *build_tce_table(struct
}
/* For the highest level, turn on all the bits */
-
i = tbl->mlbm.maxLevel;
p = tbl->mlbm.level[i].map;
m = numBits[i];
@@ -301,6 +336,10 @@ struct TceTable *build_tce_table(struct
}
}
+#ifdef CONFIG_TCE_STATS
+ build_tce_stats (tbl);
+#endif /* CONFIG_TCE_STATS */
+
return tbl;
}
@@ -364,6 +403,14 @@ static long alloc_tce_range_nolock( stru
*/
PPCDBG(PPCDBG_TCE, "alloc_tce_range_nolock: allocating block %ld, (byte=%ld, bit=%ld) order %d\n", block, i, bit, order );
tcenum = block << order;
+#ifdef CONFIG_TCE_STATS
+ if (tbl->mlbm.level[order].blk_stats) {
+ tbl->mlbm.level[order].blk_stats[block].use_cnt ++;
+ tbl->mlbm.level[order].blk_stats[block].alloc_jiffies = jiffies;
+ }
+ tbl->mlbm.level[order].use_cnt ++;
+ tbl->use_cnt ++;
+#endif /* CONFIG_TCE_STATS */
return tcenum;
}
++map;
@@ -388,6 +435,19 @@ static long alloc_tce_range_nolock( stru
if((tcenum == -1) && (order < (NUM_TCE_LEVELS - 1))) {
tcenum = alloc_tce_range_nolock( tbl, order+1 );
if ( tcenum != -1 ) {
+#ifdef CONFIG_TCE_STATS
+ /* fix up stats for 'what we actually used' */
+ if (tbl->mlbm.level[order].blk_stats) {
+ tbl->mlbm.level[order].blk_stats[(tcenum>>order)].alloc_jiffies = jiffies;
+ tbl->mlbm.level[order].blk_stats[(tcenum>>order)].use_cnt ++;
+ tbl->mlbm.level[order].blk_stats[(tcenum>>order)+1].alloc_jiffies = jiffies;
+ }
+ if (tbl->mlbm.level[order+1].blk_stats) {
+ tbl->mlbm.level[order+1].blk_stats[(tcenum>>(order+1))].alloc_jiffies = (unsigned long) -1;
+ tbl->mlbm.level[order+1].blk_stats[(tcenum>>(order+1))].use_cnt --;
+ }
+ tbl->mlbm.level[order].split_cnt ++;
+#endif /* CONFIG_TCE_STATS */
free_tce_range_nolock( tbl, tcenum+(1<<order), order );
}
}
@@ -450,6 +510,15 @@ void free_tce_range_nolock(struct TceTab
mask = 0x80 >> bit;
bytep = map + byte;
+#ifdef CONFIG_TCE_STATS
+ if (tbl->mlbm.level[order].blk_stats) {
+ if (0 == tbl->mlbm.level[order].blk_stats[block].alloc_jiffies) {
+ printk("PCI_DMA: Freeing tce that wasn't alloced: device %s, busno 0x%x tcenum %lx, order %x\n", (tbl->dn)?(tbl->dn->full_name):"?", tbl->busNumber, tcenum,order);
+ }
+ tbl->mlbm.level[order].blk_stats[block].alloc_jiffies = 0;
+ }
+#endif /* CONFIG_TCE_STATS */
+
#ifdef DEBUG_TCE
PPCDBG(PPCDBG_TCE,"free_tce_range_nolock: freeing block %ld (byte=%d, bit=%d) of order %d\n",
block, byte, bit, order);
@@ -487,6 +556,9 @@ void free_tce_range_nolock(struct TceTab
PPCDBG(PPCDBG_TCE,
"free_tce_range: buddying blocks %ld & %ld\n",
block, block+1);
+#ifdef CONFIG_TCE_STATS
+ tbl->mlbm.level[order].merge_cnt ++;
+#endif /* CONFIG_TCE_STATS */
free_tce_range_nolock( tbl, tcenum, order+1 );
}
}
@@ -689,6 +761,7 @@ void create_tce_tables_for_buses(struct
if ((1<<num_slots_ilog2) != num_slots)
num_slots_ilog2++;
phb->dma_window_size = 1 << (22 - num_slots_ilog2);
+printk ("duuuude create_tce_tables phb slots=%d size=0x%lx\n", num_slots,phb->dma_window_size);
/* Reserve 16MB of DMA space on the first PHB.
* We should probably be more careful and use firmware props.
* In reality this space is remapped, not lost. But we don't
@@ -757,8 +830,8 @@ void create_tce_tables(void) {
void create_pci_bus_tce_table( unsigned long token ) {
struct TceTable * newTceTable;
- PPCDBG(PPCDBG_TCE, "Entering create_pci_bus_tce_table.\n");
- PPCDBG(PPCDBG_TCE, "\ttoken = 0x%lx\n", token);
+ PPCDBG(PPCDBG_TCEINIT, "Entering create_pci_bus_tce_table.\n");
+ PPCDBG(PPCDBG_TCEINIT, "\ttoken = 0x%lx\n", token);
newTceTable = (struct TceTable *)kmalloc( sizeof(struct TceTable), GFP_KERNEL );
@@ -799,6 +872,9 @@ void create_pci_bus_tce_table( unsigned
getTceTableParmsPSeriesLP(phb, dn, newTceTable);
dn->tce_table = build_tce_table( newTceTable );
+#ifdef CONFIG_TCE_STATS
+ newTceTable->dn = dn;
+#endif /* CONFIG_TCE_STATS */
}
}
@@ -1084,7 +1160,7 @@ dma_addr_t pci_map_single(struct pci_dev
unsigned order, nPages;
PPCDBG(PPCDBG_TCE, "pci_map_single:\n");
- PPCDBG(PPCDBG_TCE, "\thwdev = 0x%16.16lx, size = 0x%16.16lx, direction = 0x%16.16lx, vaddr = 0x%16.16lx\n", hwdev, size, direction, vaddr);
+ PPCDBG(PPCDBG_TCE, "\thwdev = 0x%16.16lx, size = 0x%lx, direction = %ld, vaddr = 0x%16.16lx\n", hwdev, size, direction, vaddr);
if (direction == PCI_DMA_NONE)
BUG();
@@ -1297,7 +1373,7 @@ static dma_addr_t create_tces_sg(struct
/* Client asked for way to much space. This is checked later anyway */
/* It is easier to debug here for the drivers than in the tce tables.*/
if(order >= NUM_TCE_LEVELS) {
- printk("PCI_DMA: create_tces_sg size too large: 0x%llx \n",(numTces << PAGE_SHIFT));
+ printk("PCI_DMA: create_tces_sg size too large: 0x%x \n",(numTces << PAGE_SHIFT));
panic("numTces is off");
return NO_TCE;
}
@@ -1403,7 +1479,7 @@ void pci_unmap_sg( struct pci_dev *hwdev
dma_addr_t dma_end_page, dma_start_page;
PPCDBG(PPCDBG_TCE, "pci_unmap_sg:\n");
- PPCDBG(PPCDBG_TCE, "\thwdev = 0x%16.16lx, sg = 0x%16.16lx, direction = 0x%16.16lx, nelms = 0x%16.16lx\n", hwdev, sg, direction, nelms);
+ PPCDBG(PPCDBG_TCE, "\thwdev = 0x%16.16lx, sg = 0x%16.16lx, direction = %ld, nelms = %ld\n", hwdev, sg, direction, nelms);
if ( direction == PCI_DMA_NONE || nelms == 0 )
BUG();
@@ -1425,7 +1501,7 @@ void pci_unmap_sg( struct pci_dev *hwdev
/* Client asked for way to much space. This is checked later anyway */
/* It is easier to debug here for the drivers than in the tce tables.*/
if(order >= NUM_TCE_LEVELS) {
- printk("PCI_DMA: dma_start_page:0x%lx dma_end_page:0x%lx\n",dma_start_page,dma_end_page);
+ printk("PCI_DMA: dma_start_page:0x%x dma_end_page:0x%x\n",dma_start_page,dma_end_page);
printk("PCI_DMA: pci_unmap_sg size too large: 0x%x \n",(numTces << PAGE_SHIFT));
return;
}
Index: arch/ppc64/kernel/proc_pmc.c
===================================================================
RCS file: /cvs/local/sles8/arch/ppc64/kernel/proc_pmc.c,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 proc_pmc.c
--- arch/ppc64/kernel/proc_pmc.c 7 Aug 2003 03:23:04 -0000 1.1.1.1
+++ arch/ppc64/kernel/proc_pmc.c 19 Nov 2003 18:02:12 -0000
@@ -47,6 +47,12 @@
/* pci Flight Recorder AHT */
extern void proc_pciFr_init(struct proc_dir_entry *proc_ppc64_root);
+#define CONFIG_TCE_STATS
+#ifdef CONFIG_TCE_STATS
+/* PCI TCE stats interface */
+extern void proc_tce_init(struct proc_dir_entry *proc_ppc64_root);
+#endif /* CONFIG_TCE_STATS */
+
static int proc_pmc_control_mode = 0;
struct proc_dir_entry *proc_ppc64_root = NULL;
@@ -184,6 +190,11 @@ void proc_ppc64_init(void)
/* Create the /proc/ppc64/pcifr for the Pci Flight Recorder. */
proc_pciFr_init(proc_ppc64_root);
+
+#ifdef CONFIG_TCE_STATS
+ /* Create the /proc/ppc64/tce entry for TCE stats/debugging */
+ proc_tce_init (proc_ppc64_root);
+#endif /* CONFIG_TCE_STATS */
proc_ppc64_pmc_root = proc_mkdir("pmc", proc_ppc64_root);
Index: include/asm-ppc64/pci_dma.h
===================================================================
RCS file: /cvs/local/sles8/include/asm-ppc64/pci_dma.h,v
retrieving revision 1.1.1.1
diff -u -p -r1.1.1.1 pci_dma.h
--- include/asm-ppc64/pci_dma.h 7 Aug 2003 03:23:25 -0000 1.1.1.1
+++ include/asm-ppc64/pci_dma.h 19 Nov 2003 18:02:23 -0000
@@ -23,6 +23,8 @@
#include <asm/types.h>
#include <linux/spinlock.h>
+#define CONFIG_TCE_STATS
+
/*
* NUM_TCE_LEVELS defines the largest contiguous block
* of dma (tce) space we can get. NUM_TCE_LEVELS = 10
@@ -53,10 +55,29 @@ union Tce {
} tceBits;
};
+#ifdef CONFIG_TCE_STATS
+struct tce_blk_stats {
+ unsigned long alloc_jiffies; /* time when last allocated, helps find leaks */
+ unsigned int use_cnt; /* how many times this block has been alloced */
+ char direction; /* last i/o direction */
+};
+#endif /* CONFIG_TCE_STATS */
+
struct Bitmap {
unsigned long numBits;
unsigned long numBytes;
unsigned char * map;
+#ifdef CONFIG_TCE_STATS
+ unsigned int use_cnt; /* count - block of this order has been alloced */
+
+ /* The split/merge counts provide stats about the buddy system,
+ * helping debug fragmentation problems. */
+ unsigned int split_cnt; /* count - block split to make smaller blocks */
+ unsigned int merge_cnt; /* count - block buddied back up by free */
+
+ /* Individual block stats should help debug alloc leaks. */
+ struct tce_blk_stats * blk_stats;
+#endif /* CONFIG_TCE_STATS */
};
struct MultiLevelBitmap {
@@ -73,6 +94,10 @@ struct TceTable {
u64 tceType;
spinlock_t lock;
struct MultiLevelBitmap mlbm;
+#ifdef CONFIG_TCE_STATS
+ unsigned int use_cnt; /* count of times an alloc was made in this table */
+ struct device_node *dn; /* simplify diagnostics */
+#endif /* CONFIG_TCE_STATS */
};
struct TceTableManagerCB {
More information about the Linuxppc64-dev
mailing list