Skip to contentSkip to conversation

a UBIFS image makes task pdflush blocked > 120 seconds

DISCUSSION Norbert van Bolhuis 3 participants 12 messages Oct 9, 2009 – Nov 13, 2009

Subsystems (2)
Memory technology devices (MTD) Journalling flash file system V2 (JFFS2)
lore
Share & tools
lore

Norbert van Bolhuis

author
#0 lore raw

We're using a 19MB UBIFS image (preprogrammed by manufacturing) for a 156 MB NOR flash partition.

As soon as some of our application processes start reading/writing to the UBIFS the below message occurs:

INFO: task pdflush:110 blocked for more than 120 seconds.

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
pdflush D 00000000 0 110 2

the below call trace belongs to the message:

[ceb6fc10] [c0008b24] 0xc0008b24
[ceb6fc30] [c029b9a8] 0xc029b9a8 schedule [ceb6fc80] [c029c8c8] 0xc029c8c8 __mutex_lock_slowpath [ceb6fcb0] [c014211c] 0xc014211c make_reservation [ceb6fd20] [c014291c] 0xc014291c ubifs_jnl_write_inode [ceb6fd60] [c0149cc8] 0xc0149cc8 ubifs_write_inode [ceb6fd80] [c0145bbc] 0xc0145bbc ubifs_writepage [ceb6fdb0] [c005b0b8] 0xc005b0b8 __writepage [ceb6fdc0] [c005b8dc] 0xc005b8dc write_cache_pages [ceb6fe60] [c005ba50] 0xc005ba50 do_writepages [ceb6fe70] [c00a35cc] 0xc00a35cc __writeback_single_inode [ceb6fec0] [c00a3b90] 0xc00a3b90 generic_sync_sb_inodes [ceb6ff00] [c00a4330] 0xc00a4330 writeback_inodes [ceb6ff20] [c005c774] 0xc005c774 wb_kupdate [ceb6ff80] [c005cf70] 0xc005cf70 pdflush [ceb6ffd0] [c003bd30] 0xc003bd30
[ceb6fff0] [c0011480] 0xc0011480

This message repeats once. Apart from the message everything is functioning OK.

so it's the UBIFS commit_sem that's causing this.

We're using linux-2.6.28. The linux-next backport for 2.6.28 (from git://git.infradead.org/~dedekind/ubifs-v2.6.28.git) changes are in.

I guess that, initially, there's a lot of work to be done for UBI. I'm thinking about scan entire 156MB, add UBI VID/EC headers for the empty 137MB, make LEB mappings, etc..

I don't understand why this would block UBIFS/pdflush.

I'm hoping someone can explain what's going on here.

Is there a way to avoid the situation ?

#1 lore raw
Quoted 2 lines · Norbert van Bolhuis

We're using a 19MB UBIFS image (preprogrammed by manufacturing) for a 156 MB NOR flash partition.

Wow, really huge NOR. Keep in mind that we have not tested UBIFS for NOR well enough.

Quoted 27 lines

As soon as some of our application processes start reading/writing to the UBIFS the below message occurs:

INFO: task pdflush:110 blocked for more than 120 seconds.

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
pdflush D 00000000 0 110 2

the below call trace belongs to the message:

[ceb6fc10] [c0008b24] 0xc0008b24
[ceb6fc30] [c029b9a8] 0xc029b9a8 schedule [ceb6fc80] [c029c8c8] 0xc029c8c8 __mutex_lock_slowpath [ceb6fcb0] [c014211c] 0xc014211c make_reservation [ceb6fd20] [c014291c] 0xc014291c ubifs_jnl_write_inode [ceb6fd60] [c0149cc8] 0xc0149cc8 ubifs_write_inode [ceb6fd80] [c0145bbc] 0xc0145bbc ubifs_writepage [ceb6fdb0] [c005b0b8] 0xc005b0b8 __writepage [ceb6fdc0] [c005b8dc] 0xc005b8dc write_cache_pages [ceb6fe60] [c005ba50] 0xc005ba50 do_writepages [ceb6fe70] [c00a35cc] 0xc00a35cc __writeback_single_inode [ceb6fec0] [c00a3b90] 0xc00a3b90 generic_sync_sb_inodes [ceb6ff00] [c00a4330] 0xc00a4330 writeback_inodes [ceb6ff20] [c005c774] 0xc005c774 wb_kupdate [ceb6ff80] [c005cf70] 0xc005cf70 pdflush [ceb6ffd0] [c003bd30] 0xc003bd30
[ceb6fff0] [c0011480] 0xc0011480

Quoted 3 lines

This message repeats once. Apart from the message everything is functioning OK.
so it's the UBIFS commit_sem that's causing this.

Not the semaphore itself, but it is locked for too long time and we cannot acquire it for too long. Since make_reservation needs it only in read mode, it is obvious that the it is is locked somewhere in the commit code, which is strange.

How full if the FS when this happens? What is your eraseblock size?

Quoted 9 lines

We're using linux-2.6.28. The linux-next backport for 2.6.28 (from git://git.infradead.org/~dedekind/ubifs-v2.6.28.git) changes are in.

I guess that, initially, there's a lot of work to be done for UBI. I'm thinking about scan entire 156MB, add UBI VID/EC headers for the empty 137MB, make LEB mappings, etc..

I don't understand why this would block UBIFS/pdflush.

It shouldn't. UBI spends time for scanning when you attach your flash. You pay the price at the very beginning, and then it should be fast.

What I suggest you is to inject some code to UBIFS which measures for how long the 'commit_sem' is locked in "write" mode, and find the times. Then try to investigate why this actually happens. I cannot tell why this could be, off the top of my head.

Signature · 2 lines
Best Regards,
Artem Bityutskiy (Артём Битюцкий)
author
#2 lore raw
Quoted 7 lines · Artem Bityutskiy
Quoted 2 lines · Norbert van Bolhuis

We're using a 19MB UBIFS image (preprogrammed by manufacturing) for a 156 MB NOR flash partition.

Wow, really huge NOR. Keep in mind that we have not tested UBIFS for NOR well enough.

It's a MTD_CONCATENATED 128MB NOR flash + 28MB NOR flash partition. ok, that's good to realize.
Are there any (more) thorough UBIFS tests scheduled for NOR flash ?

Quoted 5 lines
Quoted 4 lines

This message repeats once. Apart from the message everything is functioning OK.
so it's the UBIFS commit_sem that's causing this.

Quoted 7 lines

Not the semaphore itself, but it is locked for too long time and we cannot acquire it for too long. Since make_reservation needs it only in read mode, it is obvious that the it is is locked somewhere in the commit code, which is strange.

How full if the FS when this happens? What is your eraseblock size?

The UBIFS image contains only 1 file (of 18MB) and a few directories. Several application processes create (small) files and make modifications. I guess that the FS contains only 20MB.
PEB-size = 131072, LEB-size = 130944

Quoted 4 lines
Quoted 4 lines

We're using linux-2.6.28. The linux-next backport for 2.6.28 (from git://git.infradead.org/~dedekind/ubifs-v2.6.28.git) changes are in.

Quoted 9 lines
Quoted 5 lines

I guess that, initially, there's a lot of work to be done for UBI. I'm thinking about scan entire 156MB, add UBI VID/EC headers for the empty 137MB, make LEB mappings, etc..

I don't understand why this would block UBIFS/pdflush.

It shouldn't. UBI spends time for scanning when you attach your flash. You pay the price at the very beginning, and then it should be fast.

but, this "problem" does occur (~ 1 minute after) the very beginning (when power is applied for the 1st time to the board).

Quoted 5 lines

What I suggest you is to inject some code to UBIFS which measures for how long the 'commit_sem' is locked in "write" mode, and find the times. Then try to investigate why this actually happens. I cannot tell why this could be, off the top of my head.

ok, will do that. I'll track commit_sem, io_mutex and ubifs_garbage_collect(). I'll report back.

Btw. stackdump is the same (2 out of 2 times).

thanks,
Norbert.

#3 lore raw
Quoted 10 lines · Norbert van Bolhuis
Quoted 6 lines · Artem Bityutskiy
Quoted 2 lines · Norbert van Bolhuis

We're using a 19MB UBIFS image (preprogrammed by manufacturing) for a 156 MB NOR flash partition.

Wow, really huge NOR. Keep in mind that we have not tested UBIFS for NOR well enough.

It's a MTD_CONCATENATED 128MB NOR flash + 28MB NOR flash partition. ok, that's good to realize.
Are there any (more) thorough UBIFS tests scheduled for NOR flash ?

Not by us. But you may do this. Although, I did test power-cut recovery for NOR recently. This was on the "Kilauea" board.

Quoted 9 lines
Quoted 9 lines
Quoted 3 lines

This message repeats once. Apart from the message everything is functioning OK.
so it's the UBIFS commit_sem that's causing this.

Not the semaphore itself, but it is locked for too long time and we cannot acquire it for too long. Since make_reservation needs it only in read mode, it is obvious that the it is is locked somewhere in the commit code, which is strange.

Quoted 7 lines
Quoted 2 lines

How full if the FS when this happens? What is your eraseblock size?

The UBIFS image contains only 1 file (of 18MB) and a few directories. Several application processes create (small) files and make modifications. I guess that the FS contains only 20MB.
PEB-size = 131072, LEB-size = 130944

Hmm, then GC should have almost no work to do.

Quoted 8 lines
Quoted 8 lines
Quoted 8 lines

We're using linux-2.6.28. The linux-next backport for 2.6.28 (from git://git.infradead.org/~dedekind/ubifs-v2.6.28.git) changes are in.

I guess that, initially, there's a lot of work to be done for UBI. I'm thinking about scan entire 156MB, add UBI VID/EC headers for the empty 137MB, make LEB mappings, etc..

Quoted 8 lines
Quoted 5 lines
Quoted 1 line

I don't understand why this would block UBIFS/pdflush.

It shouldn't. UBI spends time for scanning when you attach your flash. You pay the price at the very beginning, and then it should be fast.

but, this "problem" does occur (~ 1 minute after) the very beginning (when power is applied for the 1st time to the board).

OK.

Quoted 10 lines
Quoted 5 lines

What I suggest you is to inject some code to UBIFS which measures for how long the 'commit_sem' is locked in "write" mode, and find the times. Then try to investigate why this actually happens. I cannot tell why this could be, off the top of my head.

ok, will do that. I'll track commit_sem, io_mutex and ubifs_garbage_collect(). I'll report back.

Btw. stackdump is the same (2 out of 2 times).

OK. I really do not have any idea off the top of my head now, sorry. Try to investigate this a beet deeper.

Signature · 2 lines
Best Regards,
Artem Bityutskiy (Артём Битюцкий)
author
#4 lore raw
Quoted 9 lines
Quoted 5 lines

ok, will do that. I'll track commit_sem, io_mutex and ubifs_garbage_collect(). I'll report back.

Btw. stackdump is the same (2 out of 2 times).

OK. I really do not have any idea off the top of my head now, sorry. Try to investigate this a beet deeper.

I investigated this. It turn out it's some kind of race condition between the pdflush deamon and other tasks (e.g. events). It has everything to do the the commit_sem and io_mutex. It's not related to my preprogrammed UBIFS image (i've seen it also after a big file was written to UBIFS and a sync was done "simultaneously") nor is it related to ubifs_garbage_collect().

Here's what I did and how I conclude the above.

I logged (in memory) all commit_sem, io_mutex and ubifs_garbage_collect actions and parse the results to human readable text afterwards.
"Req" means mutex/semaphore requested. If there's no "Req" the operation has been done.

The race condition occurs for the below UBIFS pseaudo code (which is done by many UBIFS functions):

err = make_reservation () {
down_read(&c->commit_sem) /*** commit_sem, make_reservation, DOWN 1 ***/
err = reserve_space(c, jhead, len) {
...
again:
mutex_lock_nested(&wbuf->io_mutex, wbuf->jhead); /*** io_mutex, reserve_space, LOCK 1 ***/
...
avail = c->leb_size - wbuf->offs - wbuf->used;
if (wbuf->lnum != -1 && avail >= len)

    return 0;

}
if (!err)
return 0;
}
/* the journal head stays locked and later has to be unlocked using release_head() */ if (err)
goto out_free;
...
err = write_head(c, BASEHD, dent, len, &lnum, &dent_offs, sync);
if (err)
goto out_release;
...
release_head(c, BASEHD) {
mutex_unlock(&c->jheads[jhead].wbuf.io_mutex); /*** io_mutex, release_head, UNLOCK ***/
}
...
finish_reservation(c) {
up_read(&c->commit_sem); /*** commit_sem, finish_reservation, UP ***/
}

Normally (for one "update" I guess) the logs shows:

TIME=0000.000, M(t=8,xy=06)=commit_sem, make_reservation, Req DOWN 1 TIME=0000.000, M(t=0,xy=06)=commit_sem, make_reservation, DOWN 1 TIME=0000.000, M(t=9,xy=07)=io_mutex, reserve_space, Req LOCK 1 TIME=0000.000, M(t=1,xy=07)=io_mutex, reserve_space, LOCK 1 TIME=0000.480, M(t=9,xy=8a)=io_mutex, release_head, Req UNLOCK TIME=0000.480, M(t=1,xy=8a)=io_mutex, release_head, UNLOCK TIME=0000.480, M(t=8,xy=88)=commit_sem, finish_reservation, Req UP TIME=0000.480, M(t=0,xy=88)=commit_sem, finish_reservation, UP

when "another task" is also updating the log shows:

TIME=0304.252, M(t=8,xy=06)=commit_sem, make_reservation, Req DOWN 1 TIME=0304.252, M(t=0,xy=06)=commit_sem, make_reservation, DOWN 1 TIME=0304.252, M(t=9,xy=07)=io_mutex, reserve_space, Req LOCK 1 TIME=0304.252, M(t=1,xy=07)=io_mutex, reserve_space, LOCK 1 TIME=0304.292, M(t=8,xy=06)=commit_sem, make_reservation, Req DOWN 1
TIME=0304.292, M(t=0,xy=06)=commit_sem, make_reservation, DOWN 1 <- 2nd DOWN !?
TIME=0304.292, M(t=9,xy=07)=io_mutex, reserve_space, Req LOCK 1 TIME=0304.736, M(t=9,xy=8a)=io_mutex, release_head, Req UNLOCK TIME=0304.736, M(t=1,xy=8a)=io_mutex, release_head, UNLOCK TIME=0304.736, M(t=8,xy=88)=commit_sem, finish_reservation, Req UP TIME=0304.736, M(t=0,xy=88)=commit_sem, finish_reservation, UP TIME=0304.736, M(t=1,xy=07)=io_mutex, reserve_space, LOCK 1 TIME=0304.736, M(t=9,xy=8a)=io_mutex, release_head, Req UNLOCK TIME=0304.736, M(t=1,xy=8a)=io_mutex, release_head, UNLOCK TIME=0304.736, M(t=8,xy=88)=commit_sem, finish_reservation, Req UP TIME=0304.736, M(t=0,xy=88)=commit_sem, finish_reservation, UP

I really don't understand the commit_sem here. Is there a 2nd copy of commit_sem ?

the very first time pdflush interfers the pdflush error report shows (for which there's also a log entry):

TIME=0021.644, M(t=8,xy=06)=commit_sem, make_reservation, Req DOWN 1 TIME=0021.644, M(t=0,xy=06)=commit_sem, make_reservation, DOWN 1 TIME=0021.644, M(t=9,xy=07)=io_mutex, reserve_space, Req LOCK 1 TIME=0021.644, M(t=1,xy=07)=io_mutex, reserve_space, LOCK 1 TIME=0034.316, M(t=8,xy=06)=commit_sem, make_reservation, Req DOWN 1
TIME=0034.316, M(t=0,xy=06)=commit_sem, make_reservation, DOWN 1 <- 2nd DOWN !?
TIME=0034.316, M(t=9,xy=07)=io_mutex, reserve_space, Req LOCK 1 <- pdflush blocks here
TIME=0168.868, M(t=3,xy=00)=pdflush error report TIME=0302.012, M(t=3,xy=00)=pdflush error report TIME=0303.280, M(t=9,xy=8a)=io_mutex, release_head, Req UNLOCK
TIME=0303.280, M(t=1,xy=8a)=io_mutex, release_head, UNLOCK <- pdflush can continue
TIME=0303.280, M(t=8,xy=88)=commit_sem, finish_reservation, Req UP TIME=0303.280, M(t=0,xy=88)=commit_sem, finish_reservation, UP
TIME=0303.284, M(t=1,xy=07)=io_mutex, reserve_space, LOCK 1 <- pdflush continues here
TIME=0303.284, M(t=9,xy=8a)=io_mutex, release_head, Req UNLOCK TIME=0303.284, M(t=1,xy=8a)=io_mutex, release_head, UNLOCK TIME=0303.284, M(t=8,xy=88)=commit_sem, finish_reservation, Req UP TIME=0303.284, M(t=0,xy=88)=commit_sem, finish_reservation, UP

I must admit I dont't see the root cause. I don't understand why the commit_sem doesn't seem to work. Nor do I understand why the "other task" needs to hold the io_mutex for more than 280 seconds.

If you see the reason or have any idea please let me know, otherwise I'll investigate this more thorough.

thanks,
Norbert.

#5 lore raw

Hi,

Quoted 63 lines · Norbert van Bolhuis
Quoted 8 lines
Quoted 4 lines

ok, will do that. I'll track commit_sem, io_mutex and ubifs_garbage_collect(). I'll report back.

Btw. stackdump is the same (2 out of 2 times).

OK. I really do not have any idea off the top of my head now, sorry. Try to investigate this a beet deeper.

I investigated this. It turn out it's some kind of race condition between the pdflush deamon and other tasks (e.g. events). It has everything to do the the commit_sem and io_mutex. It's not related to my preprogrammed UBIFS image (i've seen it also after a big file was written to UBIFS and a sync was done "simultaneously") nor is it related to ubifs_garbage_collect().

Here's what I did and how I conclude the above.

I logged (in memory) all commit_sem, io_mutex and ubifs_garbage_collect actions and parse the results to human readable text afterwards.
"Req" means mutex/semaphore requested. If there's no "Req" the operation has been done.

The race condition occurs for the below UBIFS pseaudo code (which is done by many UBIFS functions):

  err = make_reservation () {
   down_read(&c->commit_sem)				/*** commit_sem, make_reservation, DOWN 1 ***/
   err = reserve_space(c, jhead, len) {
    ...
  again:
    mutex_lock_nested(&wbuf->io_mutex, wbuf->jhead);	/*** io_mutex, reserve_space, LOCK 1 ***/
    ...
    avail = c->leb_size - wbuf->offs - wbuf->used;
    if (wbuf->lnum != -1 && avail >= len)
     return 0;
   }
   if (!err)
  	return 0;
  }
  /* the journal head stays locked and later has to be unlocked using release_head() */
  if (err)
   goto out_free;
  ...
  err = write_head(c, BASEHD, dent, len, &lnum, &dent_offs, sync);
  if (err)
   goto out_release;
  ...
  release_head(c, BASEHD) {
   mutex_unlock(&c->jheads[jhead].wbuf.io_mutex);	/*** io_mutex, release_head, UNLOCK ***/
  }
  ...
  finish_reservation(c) {
   up_read(&c->commit_sem);				/*** commit_sem, finish_reservation, UP ***/
  }

Normally (for one "update" I guess) the logs shows:

Quoted 8 lines

TIME=0000.000, M(t=8,xy=06)=commit_sem, make_reservation, Req DOWN 1 TIME=0000.000, M(t=0,xy=06)=commit_sem, make_reservation, DOWN 1 TIME=0000.000, M(t=9,xy=07)=io_mutex, reserve_space, Req LOCK 1 TIME=0000.000, M(t=1,xy=07)=io_mutex, reserve_space, LOCK 1 TIME=0000.480, M(t=9,xy=8a)=io_mutex, release_head, Req UNLOCK TIME=0000.480, M(t=1,xy=8a)=io_mutex, release_head, UNLOCK TIME=0000.480, M(t=8,xy=88)=commit_sem, finish_reservation, Req UP TIME=0000.480, M(t=0,xy=88)=commit_sem, finish_reservation, UP

What are M(t= ,xy= ) ?
Would be very useful to save process ID (current()->pid) as well.

Quoted 11 lines

when "another task" is also updating the log shows:

TIME=0304.252, M(t=8,xy=06)=commit_sem, make_reservation, Req DOWN 1 TIME=0304.252, M(t=0,xy=06)=commit_sem, make_reservation, DOWN 1 TIME=0304.252, M(t=9,xy=07)=io_mutex, reserve_space, Req LOCK 1 TIME=0304.252, M(t=1,xy=07)=io_mutex, reserve_space, LOCK 1 TIME=0304.292, M(t=8,xy=06)=commit_sem, make_reservation, Req DOWN 1
TIME=0304.292, M(t=0,xy=06)=commit_sem, make_reservation, DOWN 1 <- 2nd DOWN !?

Right, this is RW semaphore, and in journal reservation we lock it for reading (down_read()), and there may be many readers at a time.

The only place this semaphore is locked for writing is the commit code, where we prohibit all journal accesses for the first phase of commit. May be there is some interference with down_write(commit_sem) ?

Quoted 11 lines

TIME=0304.292, M(t=9,xy=07)=io_mutex, reserve_space, Req LOCK 1 TIME=0304.736, M(t=9,xy=8a)=io_mutex, release_head, Req UNLOCK TIME=0304.736, M(t=1,xy=8a)=io_mutex, release_head, UNLOCK TIME=0304.736, M(t=8,xy=88)=commit_sem, finish_reservation, Req UP TIME=0304.736, M(t=0,xy=88)=commit_sem, finish_reservation, UP TIME=0304.736, M(t=1,xy=07)=io_mutex, reserve_space, LOCK 1 TIME=0304.736, M(t=9,xy=8a)=io_mutex, release_head, Req UNLOCK TIME=0304.736, M(t=1,xy=8a)=io_mutex, release_head, UNLOCK TIME=0304.736, M(t=8,xy=88)=commit_sem, finish_reservation, Req UP TIME=0304.736, M(t=0,xy=88)=commit_sem, finish_reservation, UP

Quoted 1 line

I really don't understand the commit_sem here. Is there a 2nd copy of commit_sem ?

See above.

Quoted 12 lines

the very first time pdflush interfers the pdflush error report shows (for which there's also a log entry):

TIME=0021.644, M(t=8,xy=06)=commit_sem, make_reservation, Req DOWN 1 TIME=0021.644, M(t=0,xy=06)=commit_sem, make_reservation, DOWN 1 TIME=0021.644, M(t=9,xy=07)=io_mutex, reserve_space, Req LOCK 1 TIME=0021.644, M(t=1,xy=07)=io_mutex, reserve_space, LOCK 1 TIME=0034.316, M(t=8,xy=06)=commit_sem, make_reservation, Req DOWN 1
TIME=0034.316, M(t=0,xy=06)=commit_sem, make_reservation, DOWN 1 <- 2nd DOWN !?
TIME=0034.316, M(t=9,xy=07)=io_mutex, reserve_space, Req LOCK 1 <- pdflush blocks here
TIME=0168.868, M(t=3,xy=00)=pdflush error report TIME=0302.012, M(t=3,xy=00)=pdflush error report

Please, save PIDs as well, it is very useful. So now we need to figure out why it cannot take the mutex fro so long time. You should look deeper to the first task, which took the mutex and blocks pdflush. What that task is doing. For sure it writes something to the flash, which goes down to UBI, then to MTD, then to your flash driver. And probably somewhere there the task is blocked for long time?

Quoted 12 lines

TIME=0303.280, M(t=9,xy=8a)=io_mutex, release_head, Req UNLOCK
TIME=0303.280, M(t=1,xy=8a)=io_mutex, release_head, UNLOCK <- pdflush can continue
TIME=0303.280, M(t=8,xy=88)=commit_sem, finish_reservation, Req UP TIME=0303.280, M(t=0,xy=88)=commit_sem, finish_reservation, UP
TIME=0303.284, M(t=1,xy=07)=io_mutex, reserve_space, LOCK 1 <- pdflush continues here
TIME=0303.284, M(t=9,xy=8a)=io_mutex, release_head, Req UNLOCK TIME=0303.284, M(t=1,xy=8a)=io_mutex, release_head, UNLOCK TIME=0303.284, M(t=8,xy=88)=commit_sem, finish_reservation, Req UP TIME=0303.284, M(t=0,xy=88)=commit_sem, finish_reservation, UP

Quoted 2 lines

I must admit I dont't see the root cause. I don't understand why the commit_sem doesn't seem to work.

Because it is R/W semaphore. In your investigations you looked at we
locks: the commit_sem (which is an R/W sem.) and io_mutex (which is a normal mutex). Let's discuss what they protect.

1. commit_sem serializes all FS writers vs. the commit process. While UBIFS has space in journals, tasks can just write. But once the journal is full, we have to commit. When we commit, we need to stop all writers for a short period of time (not for whole commit time). Thus, what we do is that all journal writers take the commit_sem for reading, and the commit function takes it for writing.

2. In UBIFS wa have several journal heads. We put different data to different heads. And the io_mutex is per-head mutex. 2 tasks are allowed to write at the same time to different heads. But if they want to write to the same head, they are serialized by the io_mutex.

Quoted 2 lines

Nor do I understand why the "other task" needs to hold the
io_mutex for more than 280 seconds.

You need to look deeper to that task. See where it goes next, and how it spends some that time.

It might happen to be that by the time the other task releases io_mutex, there is a third task which takes it, and by the time the third task releases the mutex, there is a fourth task which takes it. So pdflush waits very long. IOW, I think mutexes are not very fair.

However, I think that most likely the other task is just blocked for long time somewhere in UBI or MTD level, for some reasons.

Quoted 2 lines

If you see the reason or have any idea please let me know, otherwise I'll investigate this more thorough.

Try to see deeper at what the other task is doing, and store process ids as well.

HTH.

Signature · 2 lines
Best Regards,
Artem Bityutskiy (Артём Битюцкий)
author
#6 lore raw
Quoted 6 lines

Try to see deeper at what the other task is doing, and store process ids as well.

HTH.

first of all, thanks for your help with this.

please forget about "M=(t= ,xy= )", it's a internal log code which is not interesting.

OK, so now I understand commit_sem is a RW semaphore which can be acquired multiple times by readers but only once for writers. I failed to see that initially. I think this problem is not related to the commit_sem though.

I changed the logging a bit and added the PID info.
The problem is indeed caused by a third task holding the "MTD chip lock". This blocks the application which is blocking pdflush.
This 3rd task is the UBI background thread. It starts to erase many NOR PEBs very soon. To be absolutely certain I also added log entries for the do_erase_oneblock function.
To better reproduce this problem I decreased the warning threshold from 120 sec to 60 secs.

Here's the detailed info.

log entries (LE:xyz is the log entry number):
---------------------------------------------
LE:0235, TIME=3984.244, pid=0918, M(xy=00)=do_erase_oneblock, START
LE:0236, TIME=3984.836, pid=1236, M(xy=04)=commit_sem, make_reservation, Req DOWN 1 <- application creating a file
LE:0237, TIME=3984.836, pid=1236, M(xy=05)=commit_sem, make_reservation, DOWN 1 LE:0238, TIME=3984.836, pid=1236, M(xy=02)=io_mutex, reserve_space, Req LOCK 1 LE:0239, TIME=3984.836, pid=1236, M(xy=03)=io_mutex, reserve_space, LOCK 1
LE:0240, TIME=3985.100, pid=0918, M(xy=01)=do_erase_oneblock, END <- ubi_bgt0d continuing erasing LEBs
LE:0241, TIME=3985.100, pid=0918, M(xy=00)=do_erase_oneblock, START
<omitted many do_erase_oneblock END/START entries>
LE:0275, TIME=3998.608, pid=0918, M(xy=00)=do_erase_oneblock, START LE:0276, TIME=3999.256, pid=0108, M(xy=04)=commit_sem, make_reservation, Req DOWN 1 LE:0277, TIME=3999.256, pid=0108, M(xy=05)=commit_sem, make_reservation, DOWN 1
LE:0278, TIME=3999.256, pid=0108, M(xy=02)=io_mutex, reserve_space, Req LOCK 1 <- pdflush blocks here
LE:0279, TIME=3999.444, pid=0918, M(xy=01)=do_erase_oneblock, END
<omitted many do_erase_oneblock END/START entries>
LE:0433, TIME=4062.400, pid=0918, M(xy=01)=do_erase_oneblock, END LE:0434, TIME=4062.400, pid=0918, M(xy=00)=do_erase_oneblock, START LE:0435, TIME=4063.124, pid=0918, M(xy=01)=do_erase_oneblock, END LE:0436, TIME=4063.124, pid=0918, M(xy=00)=do_erase_oneblock, START LE:0437, TIME=4063.308, pid=0004, M(xy=0a)=pdflush error report LE:0438, TIME=4066.120, pid=0918, M(xy=01)=do_erase_oneblock, END LE:0439, TIME=4066.120, pid=0918, M(xy=00)=do_erase_oneblock, START LE:0440, TIME=4066.876, pid=1236, M(xy=06)=io_mutex, release_head, Req UNLOCK
LE:0441, TIME=4066.876, pid=1236, M(xy=07)=io_mutex, release_head, UNLOCK <- application unlocks io_mutex
LE:0442, TIME=4066.876, pid=1236, M(xy=08)=commit_sem, finish_reservation, Req UP LE:0443, TIME=4066.876, pid=1236, M(xy=09)=commit_sem, finish_reservation, UP
LE:0444, TIME=4066.880, pid=0108, M(xy=03)=io_mutex, reserve_space, LOCK 1 <- pdflush can continue
LE:0445, TIME=4066.880, pid=0108, M(xy=06)=io_mutex, release_head, Req UNLOCK LE:0446, TIME=4066.880, pid=0108, M(xy=07)=io_mutex, release_head, UNLOCK LE:0447, TIME=4066.880, pid=0108, M(xy=08)=commit_sem, finish_reservation, Req UP LE:0448, TIME=4066.880, pid=0108, M(xy=09)=commit_sem, finish_reservation, UP

relevant processes
------------------
pdflush D 00000000 0 108 2

Call Trace:
[ceb51b50] [7f64db78] 0x7f64db78 (unreliable)
[ceb51c10] [c0008b24] 0xc0008b24        __switch_to
[ceb51c30] [c0291e40] 0xc0291e40        schedule
[ceb51c80] [c0292d60] 0xc0292d60        __mutex_lock_slowpath
[ceb51cb0] [c013d5fc] 0xc013d5fc        make_reservation
[ceb51d20] [c013ddf8] 0xc013ddf8        ubifs_jnl_write_inode
[ceb51d60] [c014531c] 0xc014531c        ubifs_write_inode
[ceb51d80] [c01410ec] 0xc01410ec        ubifs_writepage
[ceb51db0] [c005b124] 0xc005b124        __writepage
[ceb51dc0] [c005b948] 0xc005b948        write_cache_pages
[ceb51e60] [c005babc] 0xc005babc        do_writepages
[ceb51e70] [c00a3638] 0xc00a3638        __writeback_single_inode
[ceb51ec0] [c00a3bfc] 0xc00a3bfc        generic_sync_sb_inodes
[ceb51f00] [c00a439c] 0xc00a439c        writeback_inodes
[ceb51f20] [c005c7e0] 0xc005c7e0        wb_kupdate
[ceb51f80] [c005cfdc] 0xc005cfdc        pdflush
[ceb51fd0] [c003bd88] 0xc003bd88        kthread
[ceb51ff0] [c00114a0] 0xc00114a0        kernel_thread

ubi_bgt0d R running 0 918 2

Call Trace:
[ce6e1b80] [00001032] 0x001032 (unreliable)
[ce6e1c40] [c0008b24] 0xc0008b24        __switch_to
[ce6e1c60] [c0291e40] 0xc0291e40        schedule
[ce6e1cb0] [c02926d4] 0xc02926d4        schedule_timeout
[ce6e1cf0] [c002f684] 0xc002f684        msleep
[ce6e1d00] [c01ee900] 0xc01ee900        do_erase_oneblock
[ce6e1d60] [c01e98a0] 0xc01e98a0        cfi_varsize_frob
[ce6e1da0] [c01ecdc4] 0xc01ecdc4        cfi_amdstd_erase_varsize
[ce6e1db0] [c01e30b8] 0xc01e30b8        part_erase
[ce6e1dc0] [c01e5800] 0xc01e5800        concat_erase
[ce6e1e20] [c01e30b8] 0xc01e30b8        part_erase
[ce6e1e30] [c01f8134] 0xc01f8134        do_sync_erase
[ce6e1ec0] [c01f83f0] 0xc01f83f0        ubi_io_sync_erase
[ce6e1f40] [c01f9658] 0xc01f9658        erase_worker
[ce6e1f70] [c01f8cc0] 0xc01f8cc0        do_work
[ce6e1f90] [c01fa078] 0xc01fa078        ubi_thread
[ce6e1fd0] [c003bd88] 0xc003bd88        kthread
[ce6e1ff0] [c00114a0] 0xc00114a0        kernel_thread

mainctrl D 0fbd3f00 0 1236 1215

Call Trace:
[ce7fd9f0] [00000001] 0x000001 (unreliable)
[ce7fdab0] [c0008b24] 0xc0008b24        __switch_to
[ce7fdad0] [c0291e40] 0xc0291e40        schedule
[ce7fdb20] [c01ea090] 0xc01ea090        get_chip
[ce7fdb90] [c01eb8dc] 0xc01eb8dc        cfi_amdstd_write_buffers
[ce7fdc20] [c01e2da8] 0xc01e2da8        part_write
[ce7fdc30] [c01e4128] 0xc01e4128        concat_write
[ce7fdc70] [c01e2da8] 0xc01e2da8        part_write
[ce7fdc80] [c01f7854] 0xc01f7854        ubi_io_write
[ce7fdcb0] [c01f63d4] 0xc01f63d4        ubi_eba_write_leb
[ce7fdd10] [c01f546c] 0xc01f546c        ubi_leb_write
[ce7fdd30] [c0148c6c] 0xc0148c6c        ubifs_wbuf_write_nolock
[ce7fdd70] [c013dd0c] 0xc013dd0c        write_head
[ce7fdd90] [c013e9e0] 0xc013e9e0        ubifs_jnl_update
[ce7fde00] [c0143030] 0xc0143030        ubifs_create
[ce7fde50] [c008caf8] 0xc008caf8        vfs_create
[ce7fde70] [c0090a20] 0xc0090a20        do_filp_open
[ce7fdf20] [c008155c] 0xc008155c        do_sys_open
[ce7fdf40] [c001167c] 0xc001167c        ret_from_syscall

relevant process (priorities)
-----------------------------

F S UID        PID  SPID  PPID  C PRI  NI ADDR SZ  WCHAN STIME TTY          TIME CMD
1 S root       108   108     2  0  80   0 -     0  5cf64 22:16 ?        00:00:00 [pdflush]
1 S root       918   918     2  0  75  -5 -     0 1fa2dc 22:16 ?        00:00:00 [ubi_bgt0d]
0 S root      1236  1236  1221  0  90  10 - 12617  49354 22:17 ttyS1    00:00:00 mainctrl

So the problem is that the application holding the io_mutex is blocked by the ubi bg task because of the "MTD chip lock".

I'm happy I understand the problem now, I guess it's not *that* serious. It does cause unnecessary delays however which I'd like to get rid of.

I guess it wouldn't make sense to somehow release the per-journalhead io_mutex whenever blocked by the "MTD chip lock" ?

How can I prevent the UBI background thread to erase so many NOR LEBs so soon ?
(I hope the only option is not by creating a 156MB UBIFS image (preprogrammed by manufacturing) for
our 156 MB NOR partition).

Would it make sense to lower the UBI background thread task prio ?

thanks,
Norbert.

#7 lore raw
Quoted 3 lines · Norbert van Bolhuis

OK, so now I understand commit_sem is a RW semaphore which can be acquired multiple times by readers but only once for writers. I failed to see that initially. I think this problem is not related to the commit_sem though.

OK.

Quoted 3 lines

I changed the logging a bit and added the PID info.
The problem is indeed caused by a third task holding the "MTD chip lock". This blocks the application which is blocking pdflush.

OK.

Quoted 1 line

This 3rd task is the UBI background thread. It starts to erase many NOR PEBs very soon.

The only reason I see why it would do this is because you attach an empty flash to UBI. In this case, UBI has to format it. And it is doing the formatting asynchronously, in the background thread.

The idea was that we can allow using the UBI volume even if it is not fully formatted, and format in parallel. For NAND with its fast erase it works fine. With NOR it appears to be not so goot.

Please, attach UBI, then wait until the UBI background thread is done, and then mount and start using UBIFS.

The other option is to format the flash _properly_ before attaching it to UBI. In this case the background thread will not have to do that job. Use ubiformat for this:

http://www.linux-mtd.infradead.org/faq/ubi.html#L_format_mtd

Please, confirm that you do not have this problem in that case.

Quoted 118 lines

To be absolutely certain I also added log entries for the do_erase_oneblock function.
To better reproduce this problem I decreased the warning threshold from 120 sec to 60 secs.

Here's the detailed info.

log entries (LE:xyz is the log entry number):
---------------------------------------------
LE:0235, TIME=3984.244, pid=0918, M(xy=00)=do_erase_oneblock, START
LE:0236, TIME=3984.836, pid=1236, M(xy=04)=commit_sem, make_reservation, Req DOWN 1 <- application creating a file
LE:0237, TIME=3984.836, pid=1236, M(xy=05)=commit_sem, make_reservation, DOWN 1 LE:0238, TIME=3984.836, pid=1236, M(xy=02)=io_mutex, reserve_space, Req LOCK 1 LE:0239, TIME=3984.836, pid=1236, M(xy=03)=io_mutex, reserve_space, LOCK 1
LE:0240, TIME=3985.100, pid=0918, M(xy=01)=do_erase_oneblock, END <- ubi_bgt0d continuing erasing LEBs
LE:0241, TIME=3985.100, pid=0918, M(xy=00)=do_erase_oneblock, START
<omitted many do_erase_oneblock END/START entries>
LE:0275, TIME=3998.608, pid=0918, M(xy=00)=do_erase_oneblock, START LE:0276, TIME=3999.256, pid=0108, M(xy=04)=commit_sem, make_reservation, Req DOWN 1 LE:0277, TIME=3999.256, pid=0108, M(xy=05)=commit_sem, make_reservation, DOWN 1
LE:0278, TIME=3999.256, pid=0108, M(xy=02)=io_mutex, reserve_space, Req LOCK 1 <- pdflush blocks here
LE:0279, TIME=3999.444, pid=0918, M(xy=01)=do_erase_oneblock, END
<omitted many do_erase_oneblock END/START entries>
LE:0433, TIME=4062.400, pid=0918, M(xy=01)=do_erase_oneblock, END LE:0434, TIME=4062.400, pid=0918, M(xy=00)=do_erase_oneblock, START LE:0435, TIME=4063.124, pid=0918, M(xy=01)=do_erase_oneblock, END LE:0436, TIME=4063.124, pid=0918, M(xy=00)=do_erase_oneblock, START LE:0437, TIME=4063.308, pid=0004, M(xy=0a)=pdflush error report LE:0438, TIME=4066.120, pid=0918, M(xy=01)=do_erase_oneblock, END LE:0439, TIME=4066.120, pid=0918, M(xy=00)=do_erase_oneblock, START LE:0440, TIME=4066.876, pid=1236, M(xy=06)=io_mutex, release_head, Req UNLOCK
LE:0441, TIME=4066.876, pid=1236, M(xy=07)=io_mutex, release_head, UNLOCK <- application unlocks io_mutex
LE:0442, TIME=4066.876, pid=1236, M(xy=08)=commit_sem, finish_reservation, Req UP LE:0443, TIME=4066.876, pid=1236, M(xy=09)=commit_sem, finish_reservation, UP
LE:0444, TIME=4066.880, pid=0108, M(xy=03)=io_mutex, reserve_space, LOCK 1 <- pdflush can continue
LE:0445, TIME=4066.880, pid=0108, M(xy=06)=io_mutex, release_head, Req UNLOCK LE:0446, TIME=4066.880, pid=0108, M(xy=07)=io_mutex, release_head, UNLOCK LE:0447, TIME=4066.880, pid=0108, M(xy=08)=commit_sem, finish_reservation, Req UP LE:0448, TIME=4066.880, pid=0108, M(xy=09)=commit_sem, finish_reservation, UP

relevant processes
------------------
pdflush D 00000000 0 108 2

Call Trace:
[ceb51b50] [7f64db78] 0x7f64db78 (unreliable)
[ceb51c10] [c0008b24] 0xc0008b24        __switch_to
[ceb51c30] [c0291e40] 0xc0291e40        schedule
[ceb51c80] [c0292d60] 0xc0292d60        __mutex_lock_slowpath
[ceb51cb0] [c013d5fc] 0xc013d5fc        make_reservation
[ceb51d20] [c013ddf8] 0xc013ddf8        ubifs_jnl_write_inode
[ceb51d60] [c014531c] 0xc014531c        ubifs_write_inode
[ceb51d80] [c01410ec] 0xc01410ec        ubifs_writepage
[ceb51db0] [c005b124] 0xc005b124        __writepage
[ceb51dc0] [c005b948] 0xc005b948        write_cache_pages
[ceb51e60] [c005babc] 0xc005babc        do_writepages
[ceb51e70] [c00a3638] 0xc00a3638        __writeback_single_inode
[ceb51ec0] [c00a3bfc] 0xc00a3bfc        generic_sync_sb_inodes
[ceb51f00] [c00a439c] 0xc00a439c        writeback_inodes
[ceb51f20] [c005c7e0] 0xc005c7e0        wb_kupdate
[ceb51f80] [c005cfdc] 0xc005cfdc        pdflush
[ceb51fd0] [c003bd88] 0xc003bd88        kthread
[ceb51ff0] [c00114a0] 0xc00114a0        kernel_thread

ubi_bgt0d R running 0 918 2

Call Trace:
[ce6e1b80] [00001032] 0x001032 (unreliable)
[ce6e1c40] [c0008b24] 0xc0008b24        __switch_to
[ce6e1c60] [c0291e40] 0xc0291e40        schedule
[ce6e1cb0] [c02926d4] 0xc02926d4        schedule_timeout
[ce6e1cf0] [c002f684] 0xc002f684        msleep
[ce6e1d00] [c01ee900] 0xc01ee900        do_erase_oneblock
[ce6e1d60] [c01e98a0] 0xc01e98a0        cfi_varsize_frob
[ce6e1da0] [c01ecdc4] 0xc01ecdc4        cfi_amdstd_erase_varsize
[ce6e1db0] [c01e30b8] 0xc01e30b8        part_erase
[ce6e1dc0] [c01e5800] 0xc01e5800        concat_erase
[ce6e1e20] [c01e30b8] 0xc01e30b8        part_erase
[ce6e1e30] [c01f8134] 0xc01f8134        do_sync_erase
[ce6e1ec0] [c01f83f0] 0xc01f83f0        ubi_io_sync_erase
[ce6e1f40] [c01f9658] 0xc01f9658        erase_worker
[ce6e1f70] [c01f8cc0] 0xc01f8cc0        do_work
[ce6e1f90] [c01fa078] 0xc01fa078        ubi_thread
[ce6e1fd0] [c003bd88] 0xc003bd88        kthread
[ce6e1ff0] [c00114a0] 0xc00114a0        kernel_thread

mainctrl D 0fbd3f00 0 1236 1215

Call Trace:
[ce7fd9f0] [00000001] 0x000001 (unreliable)
[ce7fdab0] [c0008b24] 0xc0008b24        __switch_to
[ce7fdad0] [c0291e40] 0xc0291e40        schedule
[ce7fdb20] [c01ea090] 0xc01ea090        get_chip
[ce7fdb90] [c01eb8dc] 0xc01eb8dc        cfi_amdstd_write_buffers
[ce7fdc20] [c01e2da8] 0xc01e2da8        part_write
[ce7fdc30] [c01e4128] 0xc01e4128        concat_write
[ce7fdc70] [c01e2da8] 0xc01e2da8        part_write
[ce7fdc80] [c01f7854] 0xc01f7854        ubi_io_write
[ce7fdcb0] [c01f63d4] 0xc01f63d4        ubi_eba_write_leb
[ce7fdd10] [c01f546c] 0xc01f546c        ubi_leb_write
[ce7fdd30] [c0148c6c] 0xc0148c6c        ubifs_wbuf_write_nolock
[ce7fdd70] [c013dd0c] 0xc013dd0c        write_head
[ce7fdd90] [c013e9e0] 0xc013e9e0        ubifs_jnl_update
[ce7fde00] [c0143030] 0xc0143030        ubifs_create
[ce7fde50] [c008caf8] 0xc008caf8        vfs_create
[ce7fde70] [c0090a20] 0xc0090a20        do_filp_open
[ce7fdf20] [c008155c] 0xc008155c        do_sys_open
[ce7fdf40] [c001167c] 0xc001167c        ret_from_syscall

relevant process (priorities)
-----------------------------

F S UID        PID  SPID  PPID  C PRI  NI ADDR SZ  WCHAN STIME TTY          TIME CMD
1 S root       108   108     2  0  80   0 -     0  5cf64 22:16 ?        00:00:00 [pdflush]
1 S root       918   918     2  0  75  -5 -     0 1fa2dc 22:16 ?        00:00:00 [ubi_bgt0d]
0 S root      1236  1236  1221  0  90  10 - 12617  49354 22:17 ttyS1    00:00:00 mainctrl
Quoted 2 lines

So the problem is that the application holding the io_mutex is blocked by the ubi bg task because of the "MTD chip lock".

Right, and the task is formatting your flash. Formatting means that for each eraseblock it
1. erases (very slow on NOR!)
2. writes the UBI headers.

Your write task (pid=1236) is then blocked in CFI. If it is unlucky, it may even wait for several block erasures, and then be able to take the lock.

Quoted 2 lines

I'm happy I understand the problem now, I guess it's not *that* serious. It does cause unnecessary delays however which I'd like to get rid of.

Try the formatting.

Quoted 6 lines

I guess it wouldn't make sense to somehow release the per-journalhead io_mutex whenever blocked by the "MTD chip lock" ?

How can I prevent the UBI background thread to erase so many NOR LEBs so soon ?
(I hope the only option is not by creating a 156MB UBIFS image (preprogrammed by manufacturing) for
our 156 MB NOR partition).

No. The option is to use ubiformat. You can use this utility for formatting, and also for flashing images, in which case it will flash data, and the rest of the eraseblocks will be formatted.

Quoted 1 line

Would it make sense to lower the UBI background thread task prio ?

That would be a hack. You can even add a 'yield()' there, that would also be a hack.

Signature · 2 lines
Best Regards,
Artem Bityutskiy (Артём Битюцкий)
#8 lore raw
Quoted 11 lines · Artem Bityutskiy
Quoted 3 lines · Norbert van Bolhuis

OK, so now I understand commit_sem is a RW semaphore which can be acquired multiple times by readers but only once for writers. I failed to see that initially. I think this problem is not related to the commit_sem though.

OK.

Quoted 3 lines

I changed the logging a bit and added the PID info.
The problem is indeed caused by a third task holding the "MTD chip lock". This blocks the application which is blocking pdflush.

Quoted 7 lines

OK.

Quoted 1 line

This 3rd task is the UBI background thread. It starts to erase many NOR PEBs very soon.

The only reason I see why it would do this is because you attach an empty flash to UBI. In this case, UBI has to format it. And it is doing the formatting asynchronously, in the background thread.

And of course, it is trivial to implement a way for userspace "flush" UBI work queue, which means you can open the UBI device, call 'fsync()', and be blocked until it is formatted. It is not implemented, but it is very easy to do.

Signature · 2 lines
Best Regards,
Artem Bityutskiy (Артём Битюцкий)
#9 lore raw
In reply to Artem Bityutskiy
Quoted 24 lines · Norbert van Bolhuis
Quoted 3 lines

OK, so now I understand commit_sem is a RW semaphore which can be acquired multiple times by readers but only once for writers. I failed to see that initially. I think this problem is not related to the commit_sem though.

OK.

Quoted 3 lines

I changed the logging a bit and added the PID info.
The problem is indeed caused by a third task holding the "MTD chip lock". This blocks the application which is blocking pdflush.

OK.

Quoted 1 line

This 3rd task is the UBI background thread. It starts to erase many NOR PEBsvery soon.

The only reason I see why it would do this is because you attach an empty flash to UBI. In this case, UBI has to format it. And it is doing the formatting asynchronously, in the background thread.

The idea was that we can allow using the UBI volume even if it is not fully formatted, and format in parallel. For NAND with its fast erase it works fine. With NOR it appears to be not so goot.

Quoted 5 lines

Please, attach UBI, then wait until the UBI background thread is done, and then mount and start using UBIFS.

The other option is to format the flash _properly_ before attaching it to UBI. In this case the background thread will not have to do that job.

Erasing blocks should never block other stuff as long as there is free space available.
I had a similar problem with JFFS2 and rebooting during erase. Turns out that if you remove some big files
and then reboot, it will hang during remount RO/umount until all flash sectors has been erased. I fixed the problem with the following patch, but it was never accepted as it is racy w.r.t module unload. Fortunately I don't use modules so I got no issues with it.

Jocke

Quoted 1 line

From 3184883eab1f0703dedc0ed3aa23e1bd94693601 Mon Sep 17 00:00:00 2001

From: Joakim Tjernlund <[email protected]>
Date: Fri, 9 Nov 2007 13:48:08 +0100
Subject: [PATCH] [JFFS2] Stop erasing blocks when rebooting.

Rebooting shortly after deleting lots of big files makes the reboot hang until all blocks has been erased, which can take minutes if there are lots of blocks to erase. This addresses the issue by moving the erasing to pdflush_operation context and testing for the superblock flags MS_RDONLY and MS_ACTIVE while erasing.

---
 fs/jffs2/erase.c |    8 ++++++++
 fs/jffs2/fs.c    |   11 ++++++++++-
 2 files changed, 18 insertions(+), 1 deletions(-)
fs/jffs2/erase.c +8 -0
index a1db918..ec95a28 100644
@@ -106,6 +106,7 @@ static void jffs2_erase_block(struct jffs2_sb_info *c,
 void jffs2_erase_pending_blocks(struct jffs2_sb_info *c, int count)
 {
 	struct jffs2_eraseblock *jeb;
+	struct super_block *sb = OFNI_BS_2SFFJ(c);
 
 	down(&c->erase_free_sem);
 

@@ -114,6 +115,13 @@ void jffs2_erase_pending_blocks(struct jffs2_sb_info *c, int count)
 	while (!list_empty(&c->erase_complete_list) ||
 	       !list_empty(&c->erase_pending_list)) {
 
+		if ((sb->s_flags & MS_RDONLY) || !(sb->s_flags & MS_ACTIVE)) {
+			spin_unlock(&c->erase_completion_lock);
+			up(&c->erase_free_sem);
+			D1(printk(KERN_DEBUG "FS readonly/inactive. "
+				  "jffs2_erase_pending_blocks leaving\n"));
+			goto done;
+		}
 		if (!list_empty(&c->erase_complete_list)) {
 			jeb = list_entry(c->erase_complete_list.next, struct jffs2_eraseblock, list);
 			list_del(&jeb->list);
fs/jffs2/fs.c +10 -1
index ed85f9a..f102607 100644
@@ -13,6 +13,7 @@
 #include <linux/kernel.h>
 #include <linux/sched.h>
 #include <linux/fs.h>
+#include <linux/writeback.h>	/* for erasing blocks */
 #include <linux/list.h>
 #include <linux/mtd/mtd.h>
 #include <linux/pagemap.h>

@@ -385,6 +386,14 @@ int jffs2_remount_fs (struct super_block *sb, int *flags, char *data)
 	return 0;
 }
 
+void do_start_erase(unsigned long sb_arg)
+{
+	struct super_block *sb = (struct super_block *) sb_arg;
+	struct jffs2_sb_info *c = JFFS2_SB_INFO(sb);
+
+	jffs2_erase_pending_blocks(c, 0);
+}
+
 void jffs2_write_super (struct super_block *sb)
 {
 	struct jffs2_sb_info *c = JFFS2_SB_INFO(sb);

@@ -395,7 +404,7 @@ void jffs2_write_super (struct super_block *sb)
 
 	D1(printk(KERN_DEBUG "jffs2_write_super()\n"));
 	jffs2_garbage_collect_trigger(c);
-	jffs2_erase_pending_blocks(c, 0);
+	pdflush_operation(do_start_erase, (unsigned long)sb);
 	jffs2_flush_wbuf_gc(c, 0);
 }

--
1.6.4.4

#10 lore raw
In reply to Norbert van Bolhuis
Quoted 21 lines · Norbert van Bolhuis

We're using a 19MB UBIFS image (preprogrammed by manufacturing) for a 156 MB NOR flash partition.

As soon as some of our application processes start reading/writing to the UBIFS the below message occurs:

INFO: task pdflush:110 blocked for more than 120 seconds.

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
pdflush D 00000000 0 110 2

the below call trace belongs to the message:

[ceb6fc10] [c0008b24] 0xc0008b24
[ceb6fc30] [c029b9a8] 0xc029b9a8 schedule [ceb6fc80] [c029c8c8] 0xc029c8c8 __mutex_lock_slowpath [ceb6fcb0] [c014211c] 0xc014211c make_reservation [ceb6fd20] [c014291c] 0xc014291c ubifs_jnl_write_inode [ceb6fd60] [c0149cc8] 0xc0149cc8 ubifs_write_inode [ceb6fd80] [c0145bbc] 0xc0145bbc ubifs_writepage [ceb6fdb0] [c005b0b8] 0xc005b0b8 __writepage [ceb6fdc0] [c005b8dc] 0xc005b8dc write_cache_pages

Quoted 8 lines

[ceb6fe60] [c005ba50] 0xc005ba50 do_writepages [ceb6fe70] [c00a35cc] 0xc00a35cc __writeback_single_inode [ceb6fec0] [c00a3b90] 0xc00a3b90 generic_sync_sb_inodes [ceb6ff00] [c00a4330] 0xc00a4330 writeback_inodes [ceb6ff20] [c005c774] 0xc005c774 wb_kupdate [ceb6ff80] [c005cf70] 0xc005cf70 pdflush [ceb6ffd0] [c003bd30] 0xc003bd30
[ceb6fff0] [c0011480] 0xc0011480

Does the stackdump always look like this?

Also, it is probably not commit_sem, because __mutex_lock_slowpath is about mutexes, so this is about mutex_lock_nested(&wbuf->io_mutex, wbuf->jhead);

Signature · 2 lines
Best Regards,
Artem Bityutskiy (Артём Битюцкий)
#11 lore raw
Quoted 31 lines · Artem Bityutskiy
Quoted 21 lines · Norbert van Bolhuis

We're using a 19MB UBIFS image (preprogrammed by manufacturing) for a 156 MB NOR flash partition.

As soon as some of our application processes start reading/writing to the UBIFS the below message occurs:

INFO: task pdflush:110 blocked for more than 120 seconds.

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
pdflush D 00000000 0 110 2

the below call trace belongs to the message:

[ceb6fc10] [c0008b24] 0xc0008b24
[ceb6fc30] [c029b9a8] 0xc029b9a8 schedule [ceb6fc80] [c029c8c8] 0xc029c8c8 __mutex_lock_slowpath [ceb6fcb0] [c014211c] 0xc014211c make_reservation [ceb6fd20] [c014291c] 0xc014291c ubifs_jnl_write_inode [ceb6fd60] [c0149cc8] 0xc0149cc8 ubifs_write_inode [ceb6fd80] [c0145bbc] 0xc0145bbc ubifs_writepage [ceb6fdb0] [c005b0b8] 0xc005b0b8 __writepage [ceb6fdc0] [c005b8dc] 0xc005b8dc write_cache_pages

Quoted 8 lines

[ceb6fe60] [c005ba50] 0xc005ba50 do_writepages [ceb6fe70] [c00a35cc] 0xc00a35cc __writeback_single_inode [ceb6fec0] [c00a3b90] 0xc00a3b90 generic_sync_sb_inodes [ceb6ff00] [c00a4330] 0xc00a4330 writeback_inodes [ceb6ff20] [c005c774] 0xc005c774 wb_kupdate [ceb6ff80] [c005cf70] 0xc005cf70 pdflush [ceb6ffd0] [c003bd30] 0xc003bd30
[ceb6fff0] [c0011480] 0xc0011480

Quoted 5 lines

Does the stackdump always look like this?

Also, it is probably not commit_sem, because __mutex_lock_slowpath is about mutexes, so this is about mutex_lock_nested(&wbuf->io_mutex, wbuf->jhead);

I guess slow GC may have this effect. Try to see how much time is spent in 'ubifs_garbage_collect()'.

Signature · 2 lines
Best Regards,
Artem Bityutskiy (Артём Битюцкий)