continue adding debug prints

src/block/bio.c

@@ -575,7 +575,9 @@ inline int bio_phys_segments(struct request_queue *q, struct bio *bio)
 {
         if (unlikely(!bio_flagged(bio, BIO_SEG_VALID)))
                 blk_recount_segments(q, bio);
-
+        if (bio->bi_disk && (bio->bi_disk->major == 8)) { // sda, sda*
+        	pr_debug(" *!* bio->bi_flags=0x%04x, bio->bi_phys_segments=0x%08x",bio->bi_flags, bio->bi_phys_segments);
+        }
         return bio->bi_phys_segments;
 }
 EXPORT_SYMBOL(bio_phys_segments);
@@ -666,7 +668,7 @@ int bio_add_pc_page(struct request_queue *q, struct bio *bio, struct page
 {
         int retried_segments = 0;
         struct bio_vec *bvec;
-
+        pr_debug(" *!*");
         /*
          * cloned bio must not modify vec list
          */
@@ -845,7 +847,7 @@ static int __bio_iov_iter_get_pages(struct bio *bio, struct iov_iter *iter)
         size_t offset;
         ssize_t size;
         size = iov_iter_get_pages(iter, pages, LONG_MAX, nr_pages, &offset);
-	pr_debug("size = %d", size);
+//      pr_debug("size = %d", size);
         if (unlikely(size <= 0)) {
                 pr_debug("size = %d <0, return -EFAULT", size);
                 return size ? size : -EFAULT;
@@ -874,6 +876,8 @@ static int __bio_iov_iter_get_pages(struct bio *bio, struct iov_iter *iter)
         bv[nr_pages - 1].bv_len -= nr_pages * PAGE_SIZE - offset - size;
 
         iov_iter_advance(iter, size);
+        pr_debug("size = %d", size);
+
         return 0;
 }
 
@@ -892,7 +896,6 @@ static int __bio_iov_iter_get_pages(struct bio *bio, struct iov_iter *iter)
 int bio_iov_iter_get_pages(struct bio *bio, struct iov_iter *iter)
 {
         unsigned short orig_vcnt = bio->bi_vcnt;
-	pr_debug("ret = %d", orig_vcnt);
         do {
                 int ret = __bio_iov_iter_get_pages(bio, iter);
 
@@ -900,7 +903,7 @@ int bio_iov_iter_get_pages(struct bio *bio, struct iov_iter *iter)
                         return bio->bi_vcnt > orig_vcnt ? 0 : ret;
 
         } while (iov_iter_count(iter) && !bio_full(bio));
-
+        pr_debug("orig_vcnt = %d, bio->bi_vcnt=%d", orig_vcnt, bio->bi_vcnt);
         return 0;
 }
 EXPORT_SYMBOL_GPL(bio_iov_iter_get_pages);
@@ -1188,7 +1191,7 @@ struct bio *bio_copy_user_iov(struct request_queue *q,
         int nr_pages;
         unsigned int len = iter->count;
         unsigned int offset = map_data ? offset_in_page(map_data->offset) : 0;
-
+        pr_debug(" *!*");
         bmd = bio_alloc_map_data(iter, gfp_mask);
         if (!bmd)
                 return ERR_PTR(-ENOMEM);
@@ -1296,7 +1299,7 @@ struct bio *bio_map_user_iov(struct request_queue *q,
         struct bio *bio;
         int ret;
         struct bio_vec *bvec;
-
+        pr_debug(" *!*");
         if (!iov_iter_count(iter))
                 return ERR_PTR(-EINVAL);
 
@@ -1433,7 +1436,7 @@ struct bio *bio_map_kern(struct request_queue *q, void *data, unsigned int len,
         const int nr_pages = end - start;
         int offset, i;
         struct bio *bio;
-
+        pr_debug(" *!*");
         bio = bio_kmalloc(gfp_mask, nr_pages);
         if (!bio)
                 return ERR_PTR(-ENOMEM);
@@ -1505,7 +1508,7 @@ struct bio *bio_copy_kern(struct request_queue *q, void *data, unsigned int len,
         struct bio *bio;
         void *p = data;
         int nr_pages = 0;
-
+        pr_debug(" *!*");
         /*
          * Overflow, abort
          */
@@ -1668,8 +1671,8 @@ void generic_start_io_acct(struct request_queue *q, int op,
                            unsigned long sectors, struct hd_struct *part)
 {
         const int sgrp = op_stat_group(op);
+        pr_debug(" *!*");
         int cpu = part_stat_lock();
-
         part_round_stats(q, cpu, part);
         part_stat_inc(cpu, part, ios[sgrp]);
         part_stat_add(cpu, part, sectors[sgrp], sectors);
@@ -1684,8 +1687,8 @@ void generic_end_io_acct(struct request_queue *q, int req_op,
 {
         unsigned long duration = jiffies - start_time;
         const int sgrp = op_stat_group(req_op);
+        pr_debug(" *!*");
         int cpu = part_stat_lock();
-
         part_stat_add(cpu, part, nsecs[sgrp], jiffies_to_nsecs(duration));
         part_round_stats(q, cpu, part);
         part_dec_in_flight(q, part, op_is_write(req_op));

src/drivers/ata/ahci_elphel.c

@@ -525,7 +525,7 @@ static void elphel_qc_prep(struct ata_queued_cmd *qc)
 	unsigned int n_elem;
 	struct scatterlist *sg;
 	struct ahci_sg *ahci_sg;
-
+//	dev_dbg(ap->dev, "is_atapi = %u, protocol=%u\n",is_atapi,qc->tf.protocol);
 	dev_dbg(ap->dev, "cmd = 0x%x, qc->tag = %u, ap->qc_active = %u, link->sactive = %u, link->active_tag = %u\n",
 			qc->tf.command, qc->tag, ap->qc_active, ap->link.sactive, ap->link.active_tag);
 	dev_dbg(ap->dev, "cmd = 0x%x, lba = %u, nob_lba = %u, nsect = %u, nob_nsect = %u\n",
@@ -557,6 +557,9 @@ static void elphel_qc_prep(struct ata_queued_cmd *qc)
 	 */
 	n_elem = 0;
 	ahci_sg = cmd_tbl + AHCI_CMD_TBL_HDR_SZ;
+	dev_dbg(ap->dev, "page_link = 0x%08lx, offs = 0x%08x, length=0x%08x, dma_address=0x%08x n_elem = %u\n",\
+			qc->sg->page_link, qc->sg->offset, qc->sg->length, qc->sg->dma_address, n_elem );
+
 	if (qc->flags & ATA_QCFLAG_DMAMAP) {
 		for_each_sg(qc->sg, sg, qc->n_elem, n_elem) {
 			dma_addr_t addr = sg_dma_address(sg);
@@ -565,6 +568,9 @@ static void elphel_qc_prep(struct ata_queued_cmd *qc)
 			ahci_sg[n_elem].addr = cpu_to_le32(addr & 0xffffffff);
 			ahci_sg[n_elem].addr_hi = cpu_to_le32((addr >> 16) >> 16);
 			ahci_sg[n_elem].flags_size = cpu_to_le32(sg_len - 1);
+
+			dev_dbg(ap->dev, "n_elem = %u, addr = 0x%x, len=%u, .addr=0x%08x .add_hi=0x%08x flags_size=0x%x\n",\
+					n_elem, addr, sg_len,  ahci_sg[n_elem].addr, ahci_sg[n_elem].addr_hi, ahci_sg[n_elem].flags_size);
 		}
 	}
 
@@ -578,7 +584,6 @@ static void elphel_qc_prep(struct ata_queued_cmd *qc)
 		opts |= AHCI_CMD_ATAPI | AHCI_CMD_PREFETCH;
 
 	ahci_fill_cmd_slot(pp, qc->tag, opts);
-
 	dev_dbg(ap->dev, "dump command table content, first %d bytes, phys addr = 0x%x:\n", 16, pp->cmd_tbl_dma);
 	print_hex_dump_bytes("", DUMP_PREFIX_OFFSET, pp->cmd_tbl, 16);
 
@@ -588,17 +593,24 @@ static void elphel_qc_prep(struct ata_queued_cmd *qc)
 	struct elphel_ahci_priv *dpriv = dev_get_dpriv(ap->dev);
 	set_dscope_tstamp(dpriv, TSTMP_CMD_SYS);
 
+	if ((qc->tf.command==ATA_CMD_WRITE) || (qc->tf.command==ATA_CMD_WRITE)) {
+		dev_dbg(ap->dev, "cmd = 0x%x, lba = %lu, nsect = %u\n",
+				qc->tf.command,
+				((long)(qc->tf.lbal + (qc->tf.lbam << 8)+ (qc->tf.lbah << 16))) +
+				(((long) (qc->tf.device & 0xf)) << 24),
+				qc->tf.nsect);
+	} else {
 		dev_dbg(ap->dev, "cmd = 0x%x, lba = %lu, nsect = %u\n",
 				qc->tf.command,
 				((long)(qc->tf.lbal + (qc->tf.lbam << 8)+ (qc->tf.lbah << 16))) +
 				(((long) (qc->tf.hob_lbal + (qc->tf.hob_lbam << 8)+ (qc->tf.hob_lbah << 16))) << 24),
 				qc->tf.nsect + (qc->tf.hob_nsect << 8));
+	}
 	//same
 	dev_dbg(ap->dev, "cmd = 0x%x, lba = %u, nob_lba = %u, nsect = %u, nob_nsect = %u\n",
 			((char *) (pp->cmd_tbl))[2],  ((char *) (pp->cmd_tbl))[4] + (((char *) (pp->cmd_tbl))[5] << 8)+ (((char *)(pp->cmd_tbl))[6] << 16),
 			((char *) (pp->cmd_tbl))[8] + (((char *)(pp->cmd_tbl))[9] << 8)+ (((char *)(pp->cmd_tbl))[10] << 16),
 			((char *) (pp->cmd_tbl))[12], ((char *) (pp->cmd_tbl))[13]);
-
 }
 
 /** Set flag @e flag in driver private structure. This function uses spin lock to access the flags variable. */

src/fs/block_dev.c

@@ -197,8 +197,9 @@ __blkdev_direct_IO_simple(struct kiocb *iocb, struct iov_iter *iter,
 	ssize_t ret;
 	blk_qc_t qc;
 	int i;
-	pr_debug("pos = %lld, nr_pages = %d, type=%d, iov_offset=0x%x, count=%d, iter->iov->iov_base=%p, iter->iov->iov_len=%d, nr_segs = %ld", \
-			pos, nr_pages, iter->type, iter->iov_offset, iter->count, iter->iov->iov_base, iter->iov->iov_len, iter->nr_segs); // pos - in file
+	pr_debug("major=%u, first minor=%u, minors=%u, name=%s", bdev->bd_disk->major, bdev->bd_disk->first_minor, bdev->bd_disk->minors,bdev->bd_disk->disk_name);
+	pr_debug("pos = %lld, nr_pages = %d, type=%d, iov_offset=0x%x, count=%d, iter->iov->iov_base=0x%x, iter->iov->iov_len=%d, nr_segs = %ld", \
+			pos, nr_pages, iter->type, iter->iov_offset, iter->count, (int)(iter->iov->iov_base), iter->iov->iov_len, iter->nr_segs); // pos - in file
 	if ((pos | iov_iter_alignment(iter)) &
 	    (bdev_logical_block_size(bdev) - 1)) {
 		pr_debug("pos = %lld, iov_iter_alignment(iter) = %ld, nr_pages = %d, bdev_logical_block_size(bdev) = %d", pos, iov_iter_alignment(iter), nr_pages, bdev_logical_block_size(bdev));
@@ -212,7 +213,8 @@ __blkdev_direct_IO_simple(struct kiocb *iocb, struct iov_iter *iter,
 		if (!vecs)
 			return -ENOMEM;
 	}
-	pr_debug("DIO_INLINE_BIO_VECS = %d, nr_pages = %d", DIO_INLINE_BIO_VECS, nr_pages);
+	pr_debug("DIO_INLINE_BIO_VECS = %d, nr_pages = %d, sizeof(struct bio)=%d, sizeof(struct bvec_iter)=%d",
+			DIO_INLINE_BIO_VECS, nr_pages, sizeof(struct bio), sizeof(struct bvec_iter)); //
 	bio_init(&bio, vecs, nr_pages);
 	bio_set_dev(&bio, bdev);
 	bio.bi_iter.bi_sector = pos >> 9;
@@ -221,7 +223,7 @@ __blkdev_direct_IO_simple(struct kiocb *iocb, struct iov_iter *iter,
 	bio.bi_end_io = blkdev_bio_end_io_simple;
 	bio.bi_ioprio = iocb->ki_ioprio;
 	ret = bio_iov_iter_get_pages(&bio, iter);
-	pr_debug("ret = %d", ret); // -14
+	pr_debug("ret = %d, bio.bi_vcnt=%d", ret, bio.bi_vcnt); // -14
 	if (unlikely(ret))
 		goto out;
 	ret = bio.bi_iter.bi_size;
@@ -234,6 +236,11 @@ __blkdev_direct_IO_simple(struct kiocb *iocb, struct iov_iter *iter,
 		bio.bi_opf = dio_bio_write_op(iocb);
 		task_io_account_write(ret);
 	}
+	print_hex_dump_bytes("", DUMP_PREFIX_OFFSET, &bio, sizeof(struct bio));
+//	pr_debug("bi_disk=0x%p, bi_sector=%llu, bi_size=%u, bi_private=0x%p, bi_vcnt=%u, bi_max_vecs=%u, bi_io_vec=0x%p, bi_pool=0x%p",
+//			bio.bi_disk, bio.bi_iter.bi_sector, bio.bi_iter.bi_size, bio.bi_private, bio.bi_vcnt, bio.bi_max_vecs, bio.bi_io_vec, bio.bi_pool);
+	pr_debug("bi_disk=0x%08x, bi_sector=%llu, bi_size=%u, bi_private=0x%08x, bi_vcnt=%u, bi_max_vecs=%u, bi_io_vec=0x%08x, bi_pool=0x%08x",
+			(int)(bio.bi_disk), bio.bi_iter.bi_sector, bio.bi_iter.bi_size, (int)(bio.bi_private), bio.bi_vcnt, bio.bi_max_vecs, (int) (bio.bi_io_vec), (int) (bio.bi_pool ));
 
 	qc = submit_bio(&bio);
 	for (;;) {
@@ -245,11 +252,15 @@ __blkdev_direct_IO_simple(struct kiocb *iocb, struct iov_iter *iter,
 			io_schedule();
 	}
 	__set_current_state(TASK_RUNNING);
-	pr_debug("after __set_current_state(TASK_RUNNING)");
+	pr_debug("after __set_current_state(TASK_RUNNING), sizeof(struct page)=%d",sizeof(struct page));
 	bio_for_each_segment_all(bvec, &bio, i) {
 		if (should_dirty && !PageCompound(bvec->bv_page))
 			set_page_dirty_lock(bvec->bv_page);
+		pr_debug("%3u: bvec->bv_page=0x%08x, phys=0x%08x bv_len=%#x, bv_offset=%#x, bvec=0x%x",i, (int) (bvec->bv_page), (int)(page_to_phys(bvec->bv_page)), bvec->bv_len, bvec->bv_offset, (int) bvec);
 		put_page(bvec->bv_page);
+		if (i < 10){
+			print_hex_dump_bytes("", DUMP_PREFIX_OFFSET, bvec->bv_page, sizeof(struct page));
+		}
 	}
 	pr_debug("bio.bi_status = %d", bio.bi_status);
 
@@ -261,6 +272,7 @@ out:
 		kfree(vecs);
 
 	bio_uninit(&bio);
+	pr_debug("uninited bio");
 
 	return ret;
 }

src/fs/read_write.c

@@ -466,13 +466,23 @@ static ssize_t new_sync_write(struct file *filp, const char __user *buf, size_t
 	struct kiocb kiocb;
 	struct iov_iter iter;
 	ssize_t ret;
+
+	loff_t debug_data = 0;
+	int debug_copied = 0;
+
 	if (!strncmp(filp->f_path.dentry->d_name.name, "sda2", 4)) {
-		pr_debug("pos=%llu, len=%d, buf=0x%p", *ppos, len, buf); // pr_debug("pos=%llu, len=%d, buf=0x%p, data=0x%llx", *ppos, len, buf, ((loff_t*) (buf))[0]);
+		pr_debug("pos=%llu, len=%d, buf=0x%p", *ppos, len, buf);
 	}
 	init_sync_kiocb(&kiocb, filp);
 	kiocb.ki_pos = *ppos;
 	iov_iter_init(&iter, WRITE, &iov, 1, len);
 
+	if (!strncmp(filp->f_path.dentry->d_name.name, "sda2", 4)) {
+		debug_copied = copy_from_user(&debug_data, iter.iov->iov_base, 8);
+		pr_debug("len=%u, base=0x%p, data=0x%llx, debug_copied=%d",\
+				iter.iov->iov_len, iter.iov->iov_base, debug_data, debug_copied);
+	}
+
 	ret = call_write_iter(filp, &kiocb, &iter);
 	BUG_ON(ret == -EIOCBQUEUED);
 	if (ret > 0)
@@ -483,10 +493,13 @@ static ssize_t new_sync_write(struct file *filp, const char __user *buf, size_t
 ssize_t __vfs_write(struct file *file, const char __user *p, size_t count,
 		    loff_t *pos)
 {
+	loff_t debug_data = 0;
+	int debug_copied = 0;
 	if (!strncmp(file->f_path.dentry->d_name.name, "sda2", 4)) {
-		pr_debug("pos=%llu, count=%d, p=0x%p", *pos, count, p); // 			pr_debug("pos=%llu, count=%d, p=0x%p, data=0x%llx", *pos, count, p, ((loff_t*) (p))[0]);
+		debug_copied = copy_from_user(&debug_data, p, 8);
+		pr_debug("pos=%llu, count=%d, p=0x%p, data=0x%llx, debug_copied=%d", *pos, count, p, debug_data, debug_copied);
+// 		pr_debug("pos=%llu, count=%d, p=0x%p, data=0x%llx", *pos, count, p, ((loff_t*) (p))[0]); // panic reading user space from kernel code
 	}
-
 	if (file->f_op->write)
 		return file->f_op->write(file, p, count, pos);
 	else if (file->f_op->write_iter)

src/lib/iov_iter.c

@@ -1192,7 +1192,7 @@ ssize_t iov_iter_get_pages(struct iov_iter *i,
 {
 	if (maxsize > i->count)
 		maxsize = i->count;
-	pr_debug("maxsize = %d, maxpages=%d, start (outut) = 0x%x ", maxsize, maxpages, *start);
+	pr_debug("maxsize = %d, maxpages=%d, start (output) = 0x%x ", maxsize, maxpages, *start);
 	if (unlikely(i->type & ITER_PIPE))
 		return pipe_get_pages(i, pages, maxsize, maxpages, start);
 	iterate_all_kinds(i, maxsize, v, ({
@@ -1205,9 +1205,13 @@ ssize_t iov_iter_get_pages(struct iov_iter *i,
 			len = maxpages * PAGE_SIZE;
 		addr &= ~(PAGE_SIZE - 1);
 		n = DIV_ROUND_UP(len, PAGE_SIZE);
+		pr_debug("iterate_iovec(), addr =0x%08lx, len=%u, n=%u, write=%u", addr, len, n, (i->type & WRITE) != WRITE);
 		res = get_user_pages_fast(addr, n, (i->type & WRITE) != WRITE, pages);
-		if (unlikely(res < 0))
+		if (unlikely(res < 0)) {
+			pr_debug("iterate_iovec(), res = %d", res);
 			return res;
+		}
+		pr_debug("iterate_iovec(), res = %d, start (output) = 0x%x", res, *start);
 		return (res == n ? len : res * PAGE_SIZE) - *start;
 	0;}),({
 		/* can't be more than PAGE_SIZE */