diff --git a/fs/9p/vfs_addr.c b/fs/9p/vfs_addr.c index 32619d146cbc..3fbfc6882c35 100644 --- a/fs/9p/vfs_addr.c +++ b/fs/9p/vfs_addr.c @@ -56,10 +56,13 @@ static void v9fs_issue_write(struct netfs_io_subrequest *subreq) struct p9_fid *fid = subreq->rreq->netfs_priv; int err, len; + trace_printk("v9fs_issue_write\n"); len = p9_client_write(fid, subreq->start, &subreq->io_iter, &err); + trace_printk("Issue write done %d err(%d)\n", len, err); if (len > 0) __set_bit(NETFS_SREQ_MADE_PROGRESS, &subreq->flags); netfs_write_subrequest_terminated(subreq, len ?: err, false); + trace_printk("Issue write subrequest terminated %d\n", len); } /** @@ -74,6 +77,7 @@ static void v9fs_issue_read(struct netfs_io_subrequest *subreq) int total, err; total = p9_client_read(fid, pos, &subreq->io_iter, &err); + trace_printk("v9fs_issue_read %d err(%d)\n", total, err); /* if we just extended the file size, any portion not in * cache won't be on server and is zeroes */ diff --git a/fs/netfs/direct_write.c b/fs/netfs/direct_write.c index 42ce53cc216e..6333b8bb4008 100644 --- a/fs/netfs/direct_write.c +++ b/fs/netfs/direct_write.c @@ -105,6 +105,7 @@ ssize_t netfs_unbuffered_write_iter_locked(struct kiocb *iocb, struct iov_iter * if (!async) { trace_netfs_rreq(wreq, netfs_rreq_trace_wait_ip); + trace_printk("Waiting on NETFS_RREQ_IN_PROGRESS!\n"); wait_on_bit(&wreq->flags, NETFS_RREQ_IN_PROGRESS, TASK_UNINTERRUPTIBLE); ret = wreq->error; diff --git a/fs/netfs/read_collect.c b/fs/netfs/read_collect.c index 23c75755ad4e..a609063db8a7 100644 --- a/fs/netfs/read_collect.c +++ b/fs/netfs/read_collect.c @@ -446,6 +446,7 @@ static void netfs_read_collection(struct netfs_io_request *rreq) task_io_account_read(rreq->transferred); trace_netfs_rreq(rreq, netfs_rreq_trace_wake_ip); + trace_printk("Read collect clearing and waking up!\n"); clear_and_wake_up_bit(NETFS_RREQ_IN_PROGRESS, &rreq->flags); trace_netfs_rreq(rreq, netfs_rreq_trace_done); diff --git a/fs/netfs/write_collect.c b/fs/netfs/write_collect.c index 3fca59e6475d..a54aa2bcc786 100644 --- a/fs/netfs/write_collect.c +++ b/fs/netfs/write_collect.c @@ -429,6 +429,7 @@ void netfs_write_collection_worker(struct work_struct *work) _debug("finished"); trace_netfs_rreq(wreq, netfs_rreq_trace_wake_ip); + trace_printk("Write collect clearing and waking up!\n"); clear_and_wake_up_bit(NETFS_RREQ_IN_PROGRESS, &wreq->flags); if (wreq->iocb) { @@ -449,10 +450,14 @@ void netfs_write_collection_worker(struct work_struct *work) */ void netfs_wake_write_collector(struct netfs_io_request *wreq, bool was_async) { + trace_printk("Wake collector\n"); if (!work_pending(&wreq->work)) { netfs_get_request(wreq, netfs_rreq_trace_get_work); - if (!queue_work(system_unbound_wq, &wreq->work)) + trace_printk("Queuing collector work\n"); + if (!queue_work(system_unbound_wq, &wreq->work)) { + trace_printk("Put request\n"); netfs_put_request(wreq, was_async, netfs_rreq_trace_put_work_nq); + } } } @@ -542,8 +547,10 @@ void netfs_write_subrequest_terminated(void *_op, ssize_t transferred_or_error, /* If we are at the head of the queue, wake up the collector, * transferring a ref to it if we were the ones to do so. */ - if (list_is_first(&subreq->rreq_link, &stream->subrequests)) + if (list_is_first(&subreq->rreq_link, &stream->subrequests)) { + trace_printk("Collector woken up from netfs_write_subrequest_terminated\n"); netfs_wake_write_collector(wreq, was_async); + } netfs_put_subrequest(subreq, was_async, netfs_sreq_trace_put_terminated); } diff --git a/fs/netfs/write_issue.c b/fs/netfs/write_issue.c index 77279fc5b5a7..22a4b793e789 100644 --- a/fs/netfs/write_issue.c +++ b/fs/netfs/write_issue.c @@ -232,8 +232,10 @@ static void netfs_do_issue_write(struct netfs_io_stream *stream, _enter("R=%x[%x],%zx", wreq->debug_id, subreq->debug_index, subreq->len); - if (test_bit(NETFS_SREQ_FAILED, &subreq->flags)) + if (test_bit(NETFS_SREQ_FAILED, &subreq->flags)) { + trace_printk("netfs_do_issue_write failed!\n"); return netfs_write_subrequest_terminated(subreq, subreq->error, false); + } trace_netfs_sreq(subreq, netfs_sreq_trace_submit); stream->issue_write(subreq); @@ -264,6 +266,7 @@ void netfs_issue_write(struct netfs_io_request *wreq, if (!subreq) return; + trace_printk("netfs_issue_write!\n"); stream->construct = NULL; subreq->io_iter.count = subreq->len; netfs_do_issue_write(stream, subreq); @@ -290,6 +293,7 @@ size_t netfs_advance_write(struct netfs_io_request *wreq, _enter("R=%x[%x]", wreq->debug_id, subreq ? subreq->debug_index : 0); if (subreq && start != subreq->start + subreq->len) { + trace_printk("netfs_issue_write from advance write!\n"); netfs_issue_write(wreq, stream); subreq = NULL; } @@ -307,6 +311,7 @@ size_t netfs_advance_write(struct netfs_io_request *wreq, if (subreq->len >= stream->sreq_max_len || subreq->nr_segs >= stream->sreq_max_segs || to_eof) { + trace_printk("netfs_issue_write from advance write! 2\n"); netfs_issue_write(wreq, stream); subreq = NULL; } @@ -397,6 +402,7 @@ static int netfs_write_folio(struct netfs_io_request *wreq, * when they were read. Note that these appear as a special * write-back group. */ + trace_printk("netfs_issue_write in folio copy\n"); if (fgroup == NETFS_FOLIO_COPY_TO_CACHE) { netfs_issue_write(wreq, upload); } else if (fgroup != wreq->group) { @@ -526,6 +532,7 @@ static int netfs_write_folio(struct netfs_io_request *wreq, */ static void netfs_end_issue_write(struct netfs_io_request *wreq) { + trace_printk("netfs_end_issue_write\n"); bool needs_poke = true; smp_wmb(); /* Write subreq lists before ALL_QUEUED. */ @@ -541,6 +548,7 @@ static void netfs_end_issue_write(struct netfs_io_request *wreq) netfs_issue_write(wreq, stream); } + trace_printk("Write collector need poke %d\n", needs_poke); if (needs_poke) netfs_wake_write_collector(wreq, false); } @@ -730,6 +738,7 @@ int netfs_unbuffered_write(struct netfs_io_request *wreq, bool may_wait, size_t break; } + trace_printk("netfs_unbuffered_write\n"); netfs_end_issue_write(wreq); _leave(" = %d", error); return error; @@ -908,6 +917,7 @@ int netfs_writeback_single(struct address_space *mapping, } stop: + trace_printk("netfs_issue_write writeback single\n"); for (int s = 0; s < NR_IO_STREAMS; s++) netfs_issue_write(wreq, &wreq->io_streams[s]); smp_wmb(); /* Write lists before ALL_QUEUED. */ diff --git a/fs/netfs/write_retry.c b/fs/netfs/write_retry.c index 545d33079a77..60a03079766b 100644 --- a/fs/netfs/write_retry.c +++ b/fs/netfs/write_retry.c @@ -43,6 +43,7 @@ static void netfs_retry_write_stream(struct netfs_io_request *wreq, iov_iter_revert(&source, subreq->len - source.count); netfs_get_subrequest(subreq, netfs_sreq_trace_get_resubmit); + trace_printk("netfs_reissue_write 1\n"); netfs_reissue_write(stream, subreq, &source); } } @@ -116,6 +117,7 @@ static void netfs_retry_write_stream(struct netfs_io_request *wreq, boundary = true; netfs_get_subrequest(subreq, netfs_sreq_trace_get_resubmit); + trace_printk("netfs_reissue_write 2\n"); netfs_reissue_write(stream, subreq, &source); if (subreq == to) break; @@ -183,6 +185,7 @@ static void netfs_retry_write_stream(struct netfs_io_request *wreq, boundary = false; } + trace_printk("netfs_reissue_write 3\n"); netfs_reissue_write(stream, subreq, &source); if (!len) break; diff --git a/net/9p/client.c b/net/9p/client.c index 09f8ced9f8bb..909c83b0e015 100644 --- a/net/9p/client.c +++ b/net/9p/client.c @@ -633,12 +633,16 @@ static struct p9_req_t *p9_client_prepare_req(struct p9_client *c, p9_debug(P9_DEBUG_MUX, "client %p op %d\n", c, type); /* we allow for any status other than disconnected */ - if (c->status == Disconnected) + if (c->status == Disconnected) { + trace_printk("p9_client_prepare_req eio 1\n"); return ERR_PTR(-EIO); + } /* if status is begin_disconnected we allow only clunk request */ - if (c->status == BeginDisconnect && type != P9_TCLUNK) + if (c->status == BeginDisconnect && type != P9_TCLUNK) { + trace_printk("p9_client_prepare_req eio 2\n"); return ERR_PTR(-EIO); + } va_copy(apc, ap); req = p9_tag_alloc(c, type, t_size, r_size, fmt, apc); @@ -690,8 +694,10 @@ p9_client_rpc(struct p9_client *c, int8_t type, const char *fmt, ...) va_start(ap, fmt); req = p9_client_prepare_req(c, type, tsize, rsize, fmt, ap); va_end(ap); - if (IS_ERR(req)) + if (IS_ERR(req)) { + trace_printk("p9_client_rpc early err return\n"); return req; + } req->tc.zc = false; req->rc.zc = false; @@ -706,9 +712,12 @@ p9_client_rpc(struct p9_client *c, int8_t type, const char *fmt, ...) err = c->trans_mod->request(c, req); if (err < 0) { /* write won't happen */ + trace_printk("write won't happnen (%d)\n", err); p9_req_put(c, req); - if (err != -ERESTARTSYS && err != -EFAULT) + if (err != -ERESTARTSYS && err != -EFAULT) { + trace_printk("Client disconnected (no write)\n"); c->status = Disconnected; + } goto recalc_sigpending; } again: @@ -721,6 +730,7 @@ p9_client_rpc(struct p9_client *c, int8_t type, const char *fmt, ...) */ smp_rmb(); + trace_printk("Wait event killable (%d) (%d) (%d) (%d)\n", err, READ_ONCE(req->status), c->status, type); if (err == -ERESTARTSYS && c->status == Connected && type == P9_TFLUSH) { sigpending = 1; @@ -731,6 +741,7 @@ p9_client_rpc(struct p9_client *c, int8_t type, const char *fmt, ...) if (READ_ONCE(req->status) == REQ_STATUS_ERROR) { p9_debug(P9_DEBUG_ERROR, "req_status error %d\n", req->t_err); err = req->t_err; + trace_printk("REQ_STATUS_ERROR (%d)\n", err); } if (err == -ERESTARTSYS && c->status == Connected) { p9_debug(P9_DEBUG_MUX, "flushing\n"); @@ -743,6 +754,8 @@ p9_client_rpc(struct p9_client *c, int8_t type, const char *fmt, ...) /* if we received the response anyway, don't signal error */ if (READ_ONCE(req->status) == REQ_STATUS_RCVD) err = 0; + + trace_printk("Flushed (%d)\n", err); } recalc_sigpending: if (sigpending) { @@ -754,11 +767,13 @@ p9_client_rpc(struct p9_client *c, int8_t type, const char *fmt, ...) goto reterr; err = p9_check_errors(c, req); + trace_printk("Check error (%d)\n", err); trace_9p_client_res(c, type, req->rc.tag, err); if (!err) return req; reterr: p9_req_put(c, req); + trace_printk("Final error (%d)\n", err); return ERR_PTR(safe_errno(err)); } @@ -808,8 +823,10 @@ static struct p9_req_t *p9_client_zc_rpc(struct p9_client *c, int8_t type, err = c->trans_mod->zc_request(c, req, uidata, uodata, inlen, olen, in_hdrlen); if (err < 0) { - if (err == -EIO) + if (err == -EIO) { + trace_printk("Client disconnected (zero_copy)\n"); c->status = Disconnected; + } if (err != -ERESTARTSYS) goto recalc_sigpending; } @@ -1093,6 +1110,7 @@ EXPORT_SYMBOL(p9_client_destroy); void p9_client_disconnect(struct p9_client *clnt) { p9_debug(P9_DEBUG_9P, "clnt %p\n", clnt); + trace_printk("Client disconnected\n"); clnt->status = Disconnected; } EXPORT_SYMBOL(p9_client_disconnect); @@ -1100,6 +1118,7 @@ EXPORT_SYMBOL(p9_client_disconnect); void p9_client_begin_disconnect(struct p9_client *clnt) { p9_debug(P9_DEBUG_9P, "clnt %p\n", clnt); + trace_printk("Client begin disconnect\n"); clnt->status = BeginDisconnect; } EXPORT_SYMBOL(p9_client_begin_disconnect); @@ -1572,11 +1591,13 @@ p9_client_read_once(struct p9_fid *fid, u64 offset, struct iov_iter *to, offset, rsize); } else { non_zc = 1; + trace_printk("RPC issue\n"); req = p9_client_rpc(clnt, P9_TREAD, "dqd", fid->fid, offset, rsize); } if (IS_ERR(req)) { *err = PTR_ERR(req); + trace_printk("read RPC issue error(%d)\n", *err); if (!non_zc) iov_iter_revert(to, count - iov_iter_count(to)); return 0; @@ -1587,12 +1608,14 @@ p9_client_read_once(struct p9_fid *fid, u64 offset, struct iov_iter *to, if (*err) { if (!non_zc) iov_iter_revert(to, count - iov_iter_count(to)); + trace_printk("p9pdu_readf error(%d)\n", *err); trace_9p_protocol_dump(clnt, &req->rc); p9_req_put(clnt, req); return 0; } if (rsize < received) { pr_err("bogus RREAD count (%d > %d)\n", received, rsize); + trace_printk("bogus read\n"); received = rsize; } @@ -1602,6 +1625,7 @@ p9_client_read_once(struct p9_fid *fid, u64 offset, struct iov_iter *to, int n = copy_to_iter(dataptr, received, to); if (n != received) { + trace_printk("copy_to_iter fault\n"); *err = -EFAULT; p9_req_put(clnt, req); return n; @@ -1642,23 +1666,29 @@ p9_client_write(struct p9_fid *fid, u64 offset, struct iov_iter *from, int *err) rsize, P9_ZC_HDR_SZ, "dqd", fid->fid, offset, rsize); } else { + trace_printk("p9_client_rpc\n"); req = p9_client_rpc(clnt, P9_TWRITE, "dqV", fid->fid, offset, rsize, from); + trace_printk("p9_client_rpc done\n"); } if (IS_ERR(req)) { iov_iter_revert(from, count - iov_iter_count(from)); *err = PTR_ERR(req); + trace_printk("p9_client_rpc error (%d)\n", *err); break; } + trace_printk("p9_pdup\n"); *err = p9pdu_readf(&req->rc, clnt->proto_version, "d", &written); if (*err) { + trace_printk("p9_pdup err(%d)\n", *err); iov_iter_revert(from, count - iov_iter_count(from)); trace_9p_protocol_dump(clnt, &req->rc); p9_req_put(clnt, req); break; } if (rsize < written) { + trace_printk("p9_pdup bogus %d %d\n", written, rsize); pr_err("bogus RWRITE count (%d > %d)\n", written, rsize); written = rsize; } @@ -1666,6 +1696,7 @@ p9_client_write(struct p9_fid *fid, u64 offset, struct iov_iter *from, int *err) p9_debug(P9_DEBUG_9P, "<<< RWRITE count %d\n", written); p9_req_put(clnt, req); + trace_printk("iter revert\n"); iov_iter_revert(from, count - written - iov_iter_count(from)); total += written; offset += written; diff --git a/net/9p/trans_fd.c b/net/9p/trans_fd.c index 196060dc6138..3c83b3855e82 100644 --- a/net/9p/trans_fd.c +++ b/net/9p/trans_fd.c @@ -196,6 +196,7 @@ static void p9_conn_cancel(struct p9_conn *m, int err) return; } + trace_printk("Connection cancelled (%d)\n", err); m->err = err; list_for_each_entry_safe(req, rtmp, &m->req_list, req_list) { @@ -233,9 +234,12 @@ p9_fd_poll(struct p9_client *client, struct poll_table_struct *pt, int *err) return EPOLLERR; } + trace_printk("p9_fd_poll rd poll\n"); ret = vfs_poll(ts->rd, pt); - if (ts->rd != ts->wr) + if (ts->rd != ts->wr) { + trace_printk("p9_fd_request wr poll\n"); ret = (ret & ~EPOLLOUT) | (vfs_poll(ts->wr, pt) & ~EPOLLIN); + } return ret; } @@ -263,9 +267,13 @@ static int p9_fd_read(struct p9_client *client, void *v, int len) p9_debug(P9_DEBUG_ERROR, "blocking read ...\n"); pos = ts->rd->f_pos; + trace_printk("Data read wait %d\n", len); ret = kernel_read(ts->rd, v, len, &pos); - if (ret <= 0 && ret != -ERESTARTSYS && ret != -EAGAIN) + trace_printk("Data read %d\n", ret); + if (ret <= 0 && ret != -ERESTARTSYS && ret != -EAGAIN) { + trace_printk("Client disconnected (fd_read)\n"); client->status = Disconnected; + } return ret; } @@ -330,6 +338,7 @@ static void p9_read_work(struct work_struct *work) if (!m->rreq || (m->rreq->status != REQ_STATUS_SENT)) { p9_debug(P9_DEBUG_ERROR, "Unexpected packet tag %d\n", m->rc.tag); + trace_printk("p9_tag_lookup error\n"); err = -EIO; goto error; } @@ -338,6 +347,7 @@ static void p9_read_work(struct work_struct *work) p9_debug(P9_DEBUG_ERROR, "requested packet size too big: %d for tag %d with capacity %zd\n", m->rc.size, m->rc.tag, m->rreq->rc.capacity); + trace_printk("capacity error\n"); err = -EIO; goto error; } @@ -348,6 +358,7 @@ static void p9_read_work(struct work_struct *work) m->rc.tag, m->rreq); p9_req_put(m->client, m->rreq); m->rreq = NULL; + trace_printk("sdata error\n"); err = -EIO; goto error; } @@ -375,6 +386,7 @@ static void p9_read_work(struct work_struct *work) p9_debug(P9_DEBUG_ERROR, "Request tag %d errored out while we were reading the reply\n", m->rc.tag); + trace_printk("request tag error %d status(%d)\n", m->rc.tag, m->rreq->status); err = -EIO; goto error; } @@ -403,6 +415,7 @@ static void p9_read_work(struct work_struct *work) return; error: + trace_printk("Connection cancel\n"); p9_conn_cancel(m, err); clear_bit(Rworksched, &m->wsched); } @@ -429,9 +442,13 @@ static int p9_fd_write(struct p9_client *client, void *v, int len) if (!(ts->wr->f_flags & O_NONBLOCK)) p9_debug(P9_DEBUG_ERROR, "blocking write ...\n"); + trace_printk("Data write wait %d\n",len); ret = kernel_write(ts->wr, v, len, &ts->wr->f_pos); - if (ret <= 0 && ret != -ERESTARTSYS && ret != -EAGAIN) + trace_printk("Data written %ld\n", ret); + if (ret <= 0 && ret != -ERESTARTSYS && ret != -EAGAIN) { + trace_printk("Client disconnected (fd_write)\n"); client->status = Disconnected; + } return ret; } @@ -519,6 +536,7 @@ static void p9_write_work(struct work_struct *work) return; error: + trace_printk("Connection cancel\n"); p9_conn_cancel(m, err); clear_bit(Wworksched, &m->wsched); } @@ -628,6 +646,7 @@ static void p9_poll_mux(struct p9_conn *m) n = p9_fd_poll(m->client, NULL, &err); if (n & (EPOLLERR | EPOLLHUP | EPOLLNVAL)) { p9_debug(P9_DEBUG_TRANS, "error mux %p err %d\n", m, n); + trace_printk("Connection cancel\n"); p9_conn_cancel(m, err); } @@ -668,12 +687,14 @@ static int p9_fd_request(struct p9_client *client, struct p9_req_t *req) struct p9_trans_fd *ts = client->trans; struct p9_conn *m = &ts->conn; + trace_printk("p9_fd_request\n"); p9_debug(P9_DEBUG_TRANS, "mux %p task %p tcall %p id %d\n", m, current, &req->tc, req->tc.id); spin_lock(&m->req_lock); if (m->err < 0) { + trace_printk("p9_fd_request error\n"); spin_unlock(&m->req_lock); return m->err; } @@ -682,13 +703,16 @@ static int p9_fd_request(struct p9_client *client, struct p9_req_t *req) list_add_tail(&req->req_list, &m->unsent_req_list); spin_unlock(&m->req_lock); + trace_printk("p9_fd_request EPOLL\n"); if (test_and_clear_bit(Wpending, &m->wsched)) n = EPOLLOUT; else n = p9_fd_poll(m->client, NULL, NULL); - if (n & EPOLLOUT && !test_and_set_bit(Wworksched, &m->wsched)) + if (n & EPOLLOUT && !test_and_set_bit(Wworksched, &m->wsched)) { + trace_printk("p9_fd_request schedule work\n"); schedule_work(&m->wq); + } return 0; } @@ -852,6 +876,7 @@ static int p9_fd_open(struct p9_client *client, int rfd, int wfd) data_race(ts->wr->f_flags |= O_NONBLOCK); client->trans = ts; + trace_printk("Client connected\n"); client->status = Connected; return 0; @@ -889,6 +914,7 @@ static int p9_socket_open(struct p9_client *client, struct socket *csocket) get_file(file); p->wr = p->rd = file; client->trans = p; + trace_printk("Client connected\n"); client->status = Connected; p->rd->f_flags |= O_NONBLOCK; @@ -920,6 +946,7 @@ static void p9_conn_destroy(struct p9_conn *m) m->wreq = NULL; } + trace_printk("Connection destroy\n"); p9_conn_cancel(m, -ECONNRESET); m->client = NULL; @@ -942,6 +969,7 @@ static void p9_fd_close(struct p9_client *client) if (!ts) return; + trace_printk("Client disconnected (fd_close)\n"); client->status = Disconnected; p9_conn_destroy(&ts->conn);