[ENBD] Doubled requests

[Arne Wiebalck]

On Wed, 14 Jan 2004, Peter T. Breuer wrote:

> It's possible - first released will go at the head of the free list
> (surely it's only a singly linked list).  First reused will come off the
> head of the free list.

Ok, I see.

>
> Need more data!

Here we go ...

data of the suspicious buffer_head:

Jan 14 11:18:53 e005 kernel: cr: Suspicious block number: 73749 (last
73749) d6e7ba80 (d6e7ba80)
Jan 14 11:18:53 e005 kernel: cr:
Jan 14 11:18:53 e005 kernel: 	 bh d6e7ba80
Jan 14 11:18:53 e005 kernel: 	 b_next 00000000
Jan 14 11:18:53 e005 kernel: 	 b_blocknr 73749
Jan 14 11:18:53 e005 kernel: 	 b_size 1024
Jan 14 11:18:53 e005 kernel: 	 b_list 1
Jan 14 11:18:53 e005 kernel: 	 b_dev 25856
Jan 14 11:18:53 e005 kernel: 	 b_count 2
Jan 14 11:18:53 e005 kernel: 	 b_rdev 25856
Jan 14 11:18:53 e005 kernel: 	 b_state 31d
Jan 14 11:18:53 e005 kernel: 	 b_flushtime 360963
Jan 14 11:18:53 e005 kernel: 	 b_next_free d6e7ba20
Jan 14 11:18:53 e005 kernel: 	 b_prev_free d7c5d440
Jan 14 11:18:53 e005 kernel: 	 b_this_page d6e7ba20
Jan 14 11:18:53 e005 kernel: 	 b_reqnext 00000000
Jan 14 11:18:53 e005 kernel: 	 b_pprev 00000000
Jan 14 11:18:53 e005 kernel: 	 b_data cacae400
Jan 14 11:18:53 e005 kernel: 	 b_page c11dae04
Jan 14 11:18:53 e005 kernel: 	 b_end_io c0139390
Jan 14 11:18:53 e005 kernel: 	 b_private c0139390
Jan 14 11:18:53 e005 kernel: 	 b_rsector 147498
Jan 14 11:18:53 e005 kernel: 	 b_wait d6e7bac8
Jan 14 11:18:53 e005 kernel: 	 b_inode_buffers d6e7bac8

I also decoded the state bits

Jan 14 11:18:53 e005 kernel: cr: 1 No: 73749 --    Uptodate:1    Dirty:0
Lock:4    Req:8    Mapped:16    New:0    Async:0    Wait_IO:0    flushTime
360963

I will also go and get some info from the "last" bh this one collides
with ...


> OK - so I understand that your device is being written to by the enbd
> server? You should be able to confirm the writes in the server itself -

That's right.

> the writes will go through the fileserver.c frontend object
> to the file.c backend object. Its methods are:
>
>    int (*write)(struct nbd_file *self, char * buf, unsigned len, u64 off);
>    int (*read )(struct nbd_file *self, char * buf, unsigned len, u64 off);
>    int (*sync )(struct nbd_file *self);
>    int (*reopen)(struct nbd_file *self);
>    int (*open)(struct nbd_file *self);
>    int (*close)(struct nbd_file *self);
>    s64 (*seek)(struct nbd_file *self, s64 off, int whence);
>
>    int lives; // =0                /* number of reopens */
>    int (*ioctl)(struct nbd_file *self, int ioctl, char *arg);
>    short pid;
>    int (*lock)(struct nbd_file *self, u64 from, s64 len, int type);
>    int (*unlock)(struct nbd_file *self, u64 from, s64 len);
>
> and they are set by the init_file() call.
>
> I would try and confirm your reading by instrumenting the write method.
> You probably can take the instrumentation from your driver, no?
>

I also thought about counting the writes inside the server. This would
give a clue if enbd (server, client, driver) or the kernel between
enbd-server and my driver is the source.

> > Since my device does not deal with reqs, but only uses a make_req_function,
> > I only see single BHs.
>
> OK. You run make_request(bh).

yes.

> This may be a timing effect. Write requests are normally "plugged"
> (blocked) by the kernel and aggregated into bigger requests, then
> released all at once to the driver.  This normally results in
> consecutive writes to the same place overwriting not the target device,
> but only the buffers held in the kernel. Then the resultant buffers are
> released.
>
> So it is hard to imagine how any two consecutive writes to the same
> place can ever appear in a driver.
>
> BUT - if the two writes arrive in the kernel either side of a kernel
> release ("unplug") event, then they would be seen in the driver. This
> would be a rare event. It would arise whenever one always wrote
> everything twice - only a few of the doubles would actually hit the
> driver instead of the kernel buffer.
>
> You say 1/100000. That is about 1/100 squared. I would estimate the
> chances of two consecutive writes to the same place falling either
> side of a kernel unplug as about 1/100, since there will be a max of
> 128 or so requests stored before release.
>
> > I'll do some testing on a UP machine, but I got little hope that it will
> > solve the issue, since I am currently running only 1 daemon anyway.
>
> Oh - well then it cannot be a collision issue in the driver :-).
> And if the driver does not say that it has done a rollback, it has not
> repeated a reuest attempt.
>

UP doesn't help.


BUT: it seems that you already "impemented" a switch for the doubled
requests, it's called "merge_requests"! in one of the last tests I forgot
to activate  it and now it transferred several 100,000 writes with no
twins. I'll investigate further ....


arne




**********************************************************************
 Arne Wiebalck                        Kirchhoff Institute for Physics
                                           Technical Computer Science
                                                  INF 227, Room 3.315
                                                   D-69120 Heidelberg

 e-mail: wiebalck at kip.uni-heidelberg.de
 web   : http://www.kip.uni-heidelberg.de    Tel.: (+49) 6221/54-9816
**********************************************************************