Nigel's current for-rafael queue - one more patch.

Nigel's current for-rafael queue - one more patch.

[Nigel Cunningham]

Hi again.

This patch continues the series I posted earlier in the day, adding
readahead support that improves the speed of reading an image by a
similar factor (66MB/s -> 229MB/s).

Regards,

Nigel

[PATCH] Hibernate: Implement readahead when resuming

[Nigel Cunningham]

Add support for submitting reads before they're needed. This greatly
improves the speed of resuming:

From

PM: Image read at 66 MB/s.

to

PM: Image read at 229 MB/s.

...and removes the need for the sync_read flag.

Signed-off-by: Nigel Cunningham <nigel@tuxonice.net>
---
 kernel/power/block_io.c |   97 ++++++++++++++++++++++++++++++++++++++++++++---
 kernel/power/power.h    |    4 --
 kernel/power/snapshot.c |    5 --
 kernel/power/swap.c     |    2 -
 4 files changed, 91 insertions(+), 17 deletions(-)

diff --git a/kernel/power/block_io.c b/kernel/power/block_io.c
index fc2e05d..5a13f80 100644
--- a/kernel/power/block_io.c
+++ b/kernel/power/block_io.c
@@ -24,6 +24,9 @@ void hib_free_buffer(void);
 static atomic_t hib_io_in_progress;
 static DECLARE_WAIT_QUEUE_HEAD(num_in_progress_wait);
 
+static int more_readahead = 1, readahead_list_size;
+static struct page *readahead_list_head, *readahead_list_tail;
+
 /**
  * hib_end_bio - bio completion function.
  * @bio: bio that has completed.
@@ -67,13 +70,14 @@ static void hib_end_bio(struct bio *bio, int err)
  *	@off	physical offset of page.
  *	@page:	page we're reading or writing.
  *	@sync:	whether the i/o should be done synchronously
+ *	@ra:	whether the page is readahead
  *
  *	Straight from the textbook - allocate and initialize the bio.
  *	If we're reading, make sure the page is marked as dirty.
  *	Then submit it and, if @sync, wait.
  */
 static int submit(int rw, struct block_device *bdev, sector_t sector,
-		struct page *page, int sync)
+		struct page *page, int sync, int ra)
 {
 	const int bio_rw = rw | REQ_SYNC | REQ_UNPLUG;
 	struct bio *bio;
@@ -95,6 +99,18 @@ static int submit(int rw, struct block_device *bdev, sector_t sector,
 	bio_get(bio);
 	atomic_inc(&hib_io_in_progress);
 
+	page->private = 0;
+
+	if (ra) {
+		if (readahead_list_head)
+			readahead_list_tail->private = (unsigned long) page;
+		else
+			readahead_list_head = page;
+
+		readahead_list_tail = page;
+		readahead_list_size++;
+	}
+
 	if (sync) {
 		submit_bio(bio_rw, bio);
 		wait_on_page_locked(page);
@@ -112,18 +128,25 @@ static int submit(int rw, struct block_device *bdev, sector_t sector,
 int hib_bio_read_page(pgoff_t page_off, void *addr, int sync)
 {
 	return submit(READ, hib_resume_bdev, page_off * (PAGE_SIZE >> 9),
-			virt_to_page(addr), sync);
+			virt_to_page(addr), sync, 0);
 }
 
 int hib_bio_write_page(pgoff_t page_off, void *addr, int sync)
 {
 	return submit(WRITE, hib_resume_bdev, page_off * (PAGE_SIZE >> 9),
-			virt_to_page(addr), sync);
+			virt_to_page(addr), sync, 0);
 }
 
 void hib_wait_on_bio_chain(void)
 {
 	wait_event(num_in_progress_wait, !atomic_read(&hib_io_in_progress));
+
+	while (readahead_list_head) {
+		struct page *next = (struct page *) readahead_list_head->private;
+		__free_page(readahead_list_head);
+		readahead_list_head = next;
+		readahead_list_size--;
+	}
 }
 
 static sector_t first_sector;
@@ -220,14 +243,76 @@ int get_swap_reader(unsigned int *flags_p, sector_t first_page)
 	return error;
 }
 
-int swap_read_page(void *buf, int sync)
+int start_one_readahead(void)
 {
 	sector_t offset;
+	struct page *ra_page;
+
+	if (!more_readahead) {
+		printk("No more readahead.\n");
+		return 0;
+	}
+
+	ra_page = alloc_pages(GFP_NOIO, 0);
+
+	/* No memory for readahead? */
+	if (!ra_page) {
+		printk("No readahead page.\n");
+		return 0;
+	}
 
 	offset = hib_extent_next(&sector_extents);
-	if (!offset)
+	if (!offset) {
+		printk("Offset zero - no more readahead.\n");
+		more_readahead = 0;
+		return 0;
+	}
+
+	printk("(1) Submitting readahead of sector %llu to page %p.\n",
+			offset, ra_page);
+
+	return submit(READ, hib_resume_bdev, offset * (PAGE_SIZE >> 9),
+			ra_page, 0, 1);
+}
+
+int start_more_readahead(void)
+{
+	int ret = 0;
+
+	while (!ret && readahead_list_size < 1000 && more_readahead)
+		ret = start_one_readahead();
+
+	return ret;
+}
+
+int swap_read_page(void *buf, int sync)
+{
+	char *ra;
+	struct page *old;
+	int err = start_more_readahead();
+
+	if (err)
+		return err;
+
+	if (!readahead_list_head) {
+		printk("No readahead left. Returning -EFAULT.\n");
 		return -EFAULT;
-	return hib_bio_read_page(offset, buf, sync);
+	}
+
+	printk("Waiting on readahead of page %p.\n", readahead_list_head);
+	wait_on_page_locked(readahead_list_head);
+
+	ra = kmap(readahead_list_head);
+	memcpy(buf, ra, PAGE_SIZE);
+	kunmap(readahead_list_head);
+
+	old = readahead_list_head;
+	readahead_list_head = (struct page *) old->private;
+	__free_page(old);
+
+	readahead_list_size--;
+
+	return 0;
 }
 
 /* Part Page I/O functions */
diff --git a/kernel/power/power.h b/kernel/power/power.h
index a9a6093..ae06ba7 100644
--- a/kernel/power/power.h
+++ b/kernel/power/power.h
@@ -105,10 +105,6 @@ struct snapshot_handle {
 	void		*buffer;	/* address of the block to read from
 					 * or write to
 					 */
-	int		sync_read;	/* Set to one to notify the caller of
-					 * snapshot_write_next() that it may
-					 * need to call wait_on_bio_chain()
-					 */
 };
 
 /* This macro returns the address from/to which the caller of
diff --git a/kernel/power/snapshot.c b/kernel/power/snapshot.c
index d3f795f..baf3cc1 100644
--- a/kernel/power/snapshot.c
+++ b/kernel/power/snapshot.c
@@ -2180,8 +2180,6 @@ int snapshot_write_next(struct snapshot_handle *handle)
 	if (handle->cur > 1 && handle->cur > nr_meta_pages + nr_copy_pages)
 		return 0;
 
-	handle->sync_read = 1;
-
 	if (!handle->cur) {
 		if (!buffer)
 			/* This makes the buffer be freed by swsusp_free() */
@@ -2214,7 +2212,6 @@ int snapshot_write_next(struct snapshot_handle *handle)
 			memory_bm_position_reset(&orig_bm);
 			restore_pblist = NULL;
 			handle->buffer = get_buffer(&orig_bm, &ca);
-			handle->sync_read = 0;
 			if (IS_ERR(handle->buffer))
 				return PTR_ERR(handle->buffer);
 		}
@@ -2223,8 +2220,6 @@ int snapshot_write_next(struct snapshot_handle *handle)
 		handle->buffer = get_buffer(&orig_bm, &ca);
 		if (IS_ERR(handle->buffer))
 			return PTR_ERR(handle->buffer);
-		if (handle->buffer != buffer)
-			handle->sync_read = 0;
 	}
 	handle->cur++;
 	return PAGE_SIZE;
diff --git a/kernel/power/swap.c b/kernel/power/swap.c
index 5669f92..cfff18b 100644
--- a/kernel/power/swap.c
+++ b/kernel/power/swap.c
@@ -340,8 +340,6 @@ static int load_image(struct snapshot_handle *snapshot, unsigned int nr_to_read)
 		error = swap_read_page(data_of(*snapshot), 0);
 		if (error)
 			break;
-		if (snapshot->sync_read)
-			hib_wait_on_bio_chain();
 		if (!(nr_pages % m))
 			printk("\b\b\b\b%3d%%", nr_pages / m);
 		nr_pages++;
-- 
1.7.0.4

Re: [linux-pm] [PATCH] Hibernate: Implement readahead when resuming

[Martin Steigerwald]

[-- Attachment #1: Type: Text/Plain, Size: 4288 bytes --]

Hi Nigel and Rafael,

Am Samstag 25 September 2010 schrieb Nigel Cunningham:
> Add support for submitting reads before they're needed. This greatly
> improves the speed of resuming:
> 
> From
> 
> PM: Image read at 66 MB/s.
> 
> to
> 
> PM: Image read at 229 MB/s.
> 
> ...and removes the need for the sync_read flag.

So

martin@shambhala:~/Computer/Shambhala/Kernel/2.6.36/tuxonice-head> git 
branch -av | grep for-rafael
* for-rafael                      d4e7490 Hibernate: Implement readahead 
when resuming
  remotes/origin/for-rafael       d4e7490 Hibernate: Implement readahead 
when resuming

martin@shambhala:~> cat /proc/version
Linux version 2.6.36-rc5-tp42-hibernate-accel-vmembase-0-00135-gd4e7490-
dirty (martin@shambhala) (gcc version 4.4.5 20100728 (prerelease) (Debian 
4.4.4-8) ) #1 PREEMPT Sat Sep 25 18:02:02 CEST 2010

basically seems to work.

But

> Signed-off-by: Nigel Cunningham <nigel@tuxonice.net>
> ---
>  kernel/power/block_io.c |   97
> ++++++++++++++++++++++++++++++++++++++++++++--- kernel/power/power.h  
>  |    4 --
>  kernel/power/snapshot.c |    5 --
>  kernel/power/swap.c     |    2 -
>  4 files changed, 91 insertions(+), 17 deletions(-)
> 
> diff --git a/kernel/power/block_io.c b/kernel/power/block_io.c
> index fc2e05d..5a13f80 100644
> --- a/kernel/power/block_io.c
> +++ b/kernel/power/block_io.c
[...]
> +	if (!offset) {
> +		printk("Offset zero - no more readahead.\n");
> +		more_readahead = 0;
> +		return 0;
> +	}
> +
> +	printk("(1) Submitting readahead of sector %llu to page %p.\n",
> +			offset, ra_page);

and

> +	if (!readahead_list_head) {
> +		printk("No readahead left. Returning -EFAULT.\n");
>  		return -EFAULT;
> -	return hib_bio_read_page(offset, buf, sync);
> +	}
> +
> +	printk("Waiting on readahead of page %p.\n", readahead_list_head);

should be made optional - activatable via a debug switch - before this 
gets merged, cause it displays a lots of these on resuming which takes 
some time in itself.

I tried 5 times:

- one with just kdm started worked nicely and really rather fast!

- four with a full blown KDE 4.5.1 session with OpenGL compositing
  - one seemed to hang prior to reinitializing the Radeon KMS DRM setup
  - three other worked just fine

I do not think that the hang is related to your changes, Nigel. The kernel 
remained stuck at the lower initial resolution and didn't seem to 
initialize the radeon KMS framebuffers at 1400x1050 properly. I didn't see 
this with 2.6.35 and userspace software suspend.

Writing and reading seems to be way faster than with userspace software 
suspend, I didn't compare with unpatched in kernel suspend. But I do not 
seem to get any numbers printed:

shambhala:~> grep "Image read" /var/log/syslog
shambhala:~#1> dmesg | grep "Image read"        
shambhala:~#1> dmesg | grep "Image writ"
shambhala:~#1> grep "Image writ" /var/log/syslog
shambhala:~#1>

The machine seems to return more quickly to an usable state. Does in 
kernel suspend save larger images? I am especially surprised as I use 
compression with userspace software suspend which I thought should speed 
up writing the image. It feels that in kernel suspend with patches from 
you, Nigel, seems to outdo userspace software suspend by quite some 
margin.

I have a quite high setting for userspace software suspend image size:

  1 # /etc/uswsusp.conf(8) -- Configuration file for s2disk/s2both·
  2 resume device = /dev/sda2
  3 compress = y
  4 early writeout = y
  5 image size = 1500
  6 shutdown method = halt

Still the machine crawls on resume for about 30 seconds or a minute before 
coming into a usable state. With patched in kernel suspend this wait for 
responsivity seems to have cut down to about 10-15 seconds.

Please note: I didn't actually measure anything of this, this is just 
subjective impressions so far. Before measuring, I think I should disable 
those debug outputs I mentioned above ;).

The ThinkPad T42 I am testing on has 2 GiB RAM. Swap is about 4 GB.

No long term observations so far. I will report how it goes.

Thanks,
-- 
Martin 'Helios' Steigerwald - http://www.Lichtvoll.de
GPG: 03B0 0D6C 0040 0710 4AFA  B82F 991B EAAC A599 84C7

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [linux-pm] [PATCH] Hibernate: Implement readahead when resuming

[Martin Steigerwald]

Am Samstag 25 September 2010 schrieb Martin Steigerwald:
> Hi Nigel and Rafael,
> 
> Am Samstag 25 September 2010 schrieb Nigel Cunningham:
> > Add support for submitting reads before they're needed. This greatly
> > improves the speed of resuming:
> > 
> > From
> > 
> > PM: Image read at 66 MB/s.
> > 
> > to
> > 
> > PM: Image read at 229 MB/s.
> > 
> > ...and removes the need for the sync_read flag.
> 
> So
> 
> martin@shambhala:~/Computer/Shambhala/Kernel/2.6.36/tuxonice-head> git
> branch -av | grep for-rafael
> * for-rafael                      d4e7490 Hibernate: Implement
> readahead when resuming
>   remotes/origin/for-rafael       d4e7490 Hibernate: Implement
> readahead when resuming
[...]
> basically seems to work.
[...]
> I tried 5 times:
> 
> - one with just kdm started worked nicely and really rather fast!
> 
> - four with a full blown KDE 4.5.1 session with OpenGL compositing
>   - one seemed to hang prior to reinitializing the Radeon KMS DRM setup
>   - three other worked just fine
> 
> I do not think that the hang is related to your changes, Nigel. The
> kernel remained stuck at the lower initial resolution and didn't seem
> to initialize the radeon KMS framebuffers at 1400x1050 properly. I
> didn't see this with 2.6.35 and userspace software suspend.

I am not so sure anymore.

I got another one of these hangs with the 2.6.36-rc5 mentioned above. See
IMG_3871.jpg for the exact display were it hung. I was able to switch view 
with Alt-F1 or something like that. And then got IMG_3873.jpg. But nothing 
happened anymore. Find these on:

http://martin-steigerwald.de/tmp/tuxonice/hang-after-resume-with-pm-
patches-for-rafael/

I now tried in kernel suspend to disk with

martin@shambhala:~> cat /proc/version
Linux version 2.6.35.5-tp42-vmembase-0-pm-avoid-oom-dirty 
(martin@shambhala) (gcc version 4.4.5 20100728 (prerelease) (Debian 
4.4.4-8) ) #4 PREEMPT Sat Sep 25 13:29:53 CEST 2010

which doesn't contain your patches, Nigel, for about 5 or 6 times and I 
did not see that hang.

So maybe something in your patches, even if just the debug output I 
mentioned, or something in 2.6.36-rc5 triggers that hang.

I will test 2.6.35.5 for a bit longer to make sure that there is no hang 
on resume prior to loading. I need to reboot this one now too, cause after 
one of the resume attempts USB stopped working with:

Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device found, 
idVendor=1307, idProduct=0330
Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device strings: Mfr=1, 
Product=2, SerialNumber=3
Sep 25 21:36:47 shambhala kernel: usb 1-3: Product: Mass Storage Device
Sep 25 21:36:47 shambhala kernel: usb 1-3: Manufacturer: Generic
Sep 25 21:36:47 shambhala kernel: usb 1-3: SerialNumber: 00000000000006
Sep 25 21:36:47 shambhala kernel: scsi3 : usb-storage 1-3:1.0
Sep 25 21:36:48 shambhala kernel: BUG: unable to handle kernel NULL 
pointer dereference at 0000002c
Sep 25 21:36:48 shambhala kernel: IP: [<c125b5de>] 
cfq_get_queue+0x33e/0x550
Sep 25 21:36:48 shambhala kernel: *pde = 00000000 
Sep 25 21:36:48 shambhala kernel: Oops: 0000 [#1] PREEMPT 
Sep 25 21:36:48 shambhala kernel: last sysfs file: 
/sys/devices/pci0000:00/0000:00:1d.7/usb1/1-3/usb_device/usbdev1
.4/uevent
Sep 25 21:36:48 shambhala kernel: Modules linked in: microcode cn 
acpi_cpufreq mperf ppdev lp vboxnetadp cpufreq_us
erspace cpufreq_stats cpufreq_conservative cpufreq_powersave vboxnetflt 
vboxdrv fuse tun usblp ohci_hcd usb_storage
 usb_libusual nls_iso8859_15 nls_iso8859_1 nls_cp850 ntfs vfat msdos fat 
reiserfs isofs udf crc_itu_t smbfs pktcdvd
 uinput radeon ttm drm_kms_helper drm i2c_algo_bit hdaps tp_smapi 
thinkpad_ec binfmt_misc dm_crypt snd_intel8x0m sn
d_intel8x0 snd_ac97_codec ac97_bus snd_pcm_oss snd_mixer_oss snd_pcm 
ipw2200 snd_seq_dummy snd_seq_oss thinkpad_acp
i hwmon snd_seq_midi libipw led_class snd_rawmidi rtc_cmos pcmcia 
intel_agp snd_seq_midi_event rtc_core nvram video
 processor i2c_i801 parport_pc rtc_lib parport ac snd_seq battery button 
yenta_socket pcmcia_rsrc pcmcia_core joyde
v output evdev agpgart snd_timer snd_seq_device snd snd_page_alloc 
cfg80211 rfkill lib80211 ipv6 autofs4 dm_mod rai
d10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq 
async_tx raid1 raid0 linear md_mod 
Sep 25 21:36:48 shambhala kernel: btrfs zlib_deflate crc32c libcrc32c 
usbhid uhci_hcd ehci_hcd sg usbcore sr_mod th
ermal cdrom [last unloaded: scsi_wait_scan]
Sep 25 21:36:48 shambhala kernel:
Sep 25 21:36:48 shambhala kernel: Pid: 10474, comm: scsi_scan_3 Not 
tainted 2.6.35.5-tp42-vmembase-0-pm-avoid-oom-d
irty #4 2373CXG/2373CXG
Sep 25 21:36:48 shambhala kernel: EIP: 0060:[<c125b5de>] EFLAGS: 00010086 
CPU: 0
Sep 25 21:36:48 shambhala kernel: EIP is at cfq_get_queue+0x33e/0x550
Sep 25 21:36:48 shambhala kernel: EAX: f4d18a80 EBX: f5c9e000 ECX: 
00000001 EDX: 00000000
Sep 25 21:36:48 shambhala kernel: ESI: f5c9e108 EDI: f4976000 EBP: 
dc889cdc ESP: dc889c64
Sep 25 21:36:48 shambhala kernel: DS: 007b ES: 007b FS: 0000 GS: 00e0 SS: 
0068
Sep 25 21:36:48 shambhala kernel: Process scsi_scan_3 (pid: 10474, 
ti=dc888000 task=ed8c8000 task.ti=dc888000)
Sep 25 21:36:48 shambhala kernel: Stack:
Sep 25 21:36:48 shambhala kernel: 00000000 dc889c7c c102a154 c1a4bfa0 
00008010 00000010 ed8c8000 f5c9e044
Sep 25 21:36:48 shambhala kernel: <0> 00000001 f4976020 f5c9e028 f5c9e0d0 
f4976444 01cea7c8 f4d18a80 00000030
Sep 25 21:36:48 shambhala kernel: <0> f49763ac f4759600 f41fbcc0 01000202 
000000fc 00000000 00000000 00000003
Sep 25 21:36:48 shambhala kernel: Call Trace:
Sep 25 21:36:48 shambhala kernel: [<c102a154>] ? cpuacct_charge+0x44/0x50
Sep 25 21:36:48 shambhala kernel: [<c125b993>] ? 
cfq_set_request+0x1a3/0x410
Sep 25 21:36:48 shambhala kernel: [<c10a9c43>] ? 
mempool_alloc_slab+0x13/0x20
Sep 25 21:36:48 shambhala kernel: [<c125b7f0>] ? cfq_set_request+0x0/0x410
Sep 25 21:36:48 shambhala kernel: [<c12463f7>] ? elv_set_request+0x17/0x30
Sep 25 21:36:48 shambhala kernel: [<c124c95c>] ? get_request+0x31c/0x340
Sep 25 21:36:48 shambhala kernel: [<c124c9a2>] ? 
get_request_wait+0x22/0x1a0
Sep 25 21:36:48 shambhala kernel: [<c12f110a>] ? 
attribute_container_add_device+0x11a/0x1e0
Sep 25 21:36:48 shambhala kernel: [<c1268d81>] ? kvasprintf+0x41/0x50
Sep 25 21:36:48 shambhala kernel: [<c124cfbb>] ? blk_get_request+0x5b/0x90
Sep 25 21:36:48 shambhala kernel: [<c1308998>] ? scsi_execute+0x28/0x240
Sep 25 21:36:48 shambhala kernel: [<c130a627>] ? 
scsi_execute_req+0x87/0x160
Sep 25 21:36:48 shambhala kernel: [<c130bb6c>] ? 
scsi_probe_and_add_lun+0x1ec/0x9f0
Sep 25 21:36:48 shambhala kernel: [<c1268d81>] ? kvasprintf+0x41/0x50
Sep 25 21:36:48 shambhala kernel: [<c12e9b24>] ? trace_kmalloc+0x54/0x90
Sep 25 21:36:48 shambhala kernel: [<c130c7e0>] ? 
__scsi_scan_target+0xe0/0x580
Sep 25 21:36:48 shambhala kernel: [<c102a154>] ? cpuacct_charge+0x44/0x50
Sep 25 21:36:48 shambhala kernel: [<c102a154>] ? cpuacct_charge+0x44/0x50
Sep 25 21:36:48 shambhala kernel: [<c102e2f5>] ? update_curr+0x1b5/0x290
Sep 25 21:36:48 shambhala kernel: [<c130cd06>] ? 
scsi_scan_channel+0x86/0xa0
Sep 25 21:36:48 shambhala kernel: [<c130cde9>] ? 
scsi_scan_host_selected+0xc9/0x120
Sep 25 21:36:48 shambhala kernel: [<c130cec0>] ? do_scan_async+0x0/0x180
Sep 25 21:36:48 shambhala kernel: [<c130cebd>] ? 
do_scsi_scan_host+0x7d/0x80
Sep 25 21:36:48 shambhala kernel: [<c130ced8>] ? do_scan_async+0x18/0x180
Sep 25 21:36:48 shambhala kernel: [<c13fa837>] ? 
preempt_schedule+0x37/0x50
Sep 25 21:36:48 shambhala kernel: [<c130cec0>] ? do_scan_async+0x0/0x180
Sep 25 21:36:48 shambhala kernel: [<c10531f4>] ? kthread+0x74/0x80
Sep 25 21:36:48 shambhala kernel: [<c1053180>] ? kthread+0x0/0x80
Sep 25 21:36:48 shambhala kernel: [<c100347e>] ? 
kernel_thread_helper+0x6/0x10
Sep 25 21:36:48 shambhala kernel: Code: e4 83 45 d8 54 83 7d e4 03 0f 85 
ee fe ff ff 8b 03 c7 83 64 02 00 00 01 00 00 00 83 e0 03 09 d8 89 03 8b 45 
c0 8b 90 58 01 00 00 <8b> 42 2c 85 c0 74 78 8d 55 ec 89 54 24 0c 8d 55 f0 
89 54 24 08 
Sep 25 21:36:48 shambhala kernel: EIP: [<c125b5de>] 
cfq_get_queue+0x33e/0x550 SS:ESP 0068:dc889c64
Sep 25 21:36:48 shambhala kernel: CR2: 000000000000002c
Sep 25 21:36:48 shambhala kernel: ---[ end trace eecaeed94ae31965 ]---
Sep 25 21:36:48 shambhala kernel: note: scsi_scan_3[10474] exited with 
preempt_count 1

Maybe the USB system has an powermanagement related issue that in kernel 
suspend triggers more easily than userspace software suspend? I didn't see 
this one before. But well, this is a bug I will report in 
bugzilla.kernel.org.

Ciao,
-- 
Martin 'Helios' Steigerwald - http://www.Lichtvoll.de
GPG: 03B0 0D6C 0040 0710 4AFA  B82F 991B EAAC A599 84C7

with init=/bin/systemd USB/eSATA external mass storage no longer works (was: Re: [linux-pm] [PATCH] Hibernate: Implement readahead when resuming)

[Martin Steigerwald]

[-- Attachment #1: Type: Text/Plain, Size: 7788 bytes --]

Cc'd Lennart regarding my finding that with init=/bin/systemd USB and eSATA 
mass storage does no longer work.

Am Samstag 25 September 2010 schrieb Martin Steigerwald:
> I will test 2.6.35.5 for a bit longer to make sure that there is no
> hang  on resume prior to loading. I need to reboot this one now too,
> cause after one of the resume attempts USB stopped working with:
> 
> Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device found, 
> idVendor=1307, idProduct=0330
> Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device strings:
> Mfr=1,  Product=2, SerialNumber=3
> Sep 25 21:36:47 shambhala kernel: usb 1-3: Product: Mass Storage Device
> Sep 25 21:36:47 shambhala kernel: usb 1-3: Manufacturer: Generic
> Sep 25 21:36:47 shambhala kernel: usb 1-3: SerialNumber: 00000000000006
> Sep 25 21:36:47 shambhala kernel: scsi3 : usb-storage 1-3:1.0
> Sep 25 21:36:48 shambhala kernel: BUG: unable to handle kernel NULL 
> pointer dereference at 0000002c
> Sep 25 21:36:48 shambhala kernel: IP: [<c125b5de>] 
> cfq_get_queue+0x33e/0x550
> Sep 25 21:36:48 shambhala kernel: *pde = 00000000 
> Sep 25 21:36:48 shambhala kernel: Oops: 0000 [#1] PREEMPT 
> Sep 25 21:36:48 shambhala kernel: last sysfs file: 
> /sys/devices/pci0000:00/0000:00:1d.7/usb1/1-3/usb_device/usbdev1
> .4/uevent
> Sep 25 21:36:48 shambhala kernel: Modules linked in: microcode cn 
> acpi_cpufreq mperf ppdev lp vboxnetadp cpufreq_us
> erspace cpufreq_stats cpufreq_conservative cpufreq_powersave
> vboxnetflt  vboxdrv fuse tun usblp ohci_hcd usb_storage
>  usb_libusual nls_iso8859_15 nls_iso8859_1 nls_cp850 ntfs vfat msdos
> fat  reiserfs isofs udf crc_itu_t smbfs pktcdvd
>  uinput radeon ttm drm_kms_helper drm i2c_algo_bit hdaps tp_smapi 
> thinkpad_ec binfmt_misc dm_crypt snd_intel8x0m sn
> d_intel8x0 snd_ac97_codec ac97_bus snd_pcm_oss snd_mixer_oss snd_pcm 
> ipw2200 snd_seq_dummy snd_seq_oss thinkpad_acp
> i hwmon snd_seq_midi libipw led_class snd_rawmidi rtc_cmos pcmcia 
> intel_agp snd_seq_midi_event rtc_core nvram video
>  processor i2c_i801 parport_pc rtc_lib parport ac snd_seq battery
> button  yenta_socket pcmcia_rsrc pcmcia_core joyde
> v output evdev agpgart snd_timer snd_seq_device snd snd_page_alloc 
> cfg80211 rfkill lib80211 ipv6 autofs4 dm_mod rai
> d10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov
> raid6_pq  async_tx raid1 raid0 linear md_mod
> Sep 25 21:36:48 shambhala kernel: btrfs zlib_deflate crc32c libcrc32c 
> usbhid uhci_hcd ehci_hcd sg usbcore sr_mod th
> ermal cdrom [last unloaded: scsi_wait_scan]
> Sep 25 21:36:48 shambhala kernel:
> Sep 25 21:36:48 shambhala kernel: Pid: 10474, comm: scsi_scan_3 Not 
> tainted 2.6.35.5-tp42-vmembase-0-pm-avoid-oom-d
> irty #4 2373CXG/2373CXG
> Sep 25 21:36:48 shambhala kernel: EIP: 0060:[<c125b5de>] EFLAGS:
> 00010086  CPU: 0
> Sep 25 21:36:48 shambhala kernel: EIP is at cfq_get_queue+0x33e/0x550
> Sep 25 21:36:48 shambhala kernel: EAX: f4d18a80 EBX: f5c9e000 ECX: 
> 00000001 EDX: 00000000
> Sep 25 21:36:48 shambhala kernel: ESI: f5c9e108 EDI: f4976000 EBP: 
> dc889cdc ESP: dc889c64
> Sep 25 21:36:48 shambhala kernel: DS: 007b ES: 007b FS: 0000 GS: 00e0
> SS:  0068
> Sep 25 21:36:48 shambhala kernel: Process scsi_scan_3 (pid: 10474, 
> ti=dc888000 task=ed8c8000 task.ti=dc888000)
> Sep 25 21:36:48 shambhala kernel: Stack:
> Sep 25 21:36:48 shambhala kernel: 00000000 dc889c7c c102a154 c1a4bfa0 
> 00008010 00000010 ed8c8000 f5c9e044
> Sep 25 21:36:48 shambhala kernel: <0> 00000001 f4976020 f5c9e028
> f5c9e0d0  f4976444 01cea7c8 f4d18a80 00000030
> Sep 25 21:36:48 shambhala kernel: <0> f49763ac f4759600 f41fbcc0
> 01000202  000000fc 00000000 00000000 00000003
> Sep 25 21:36:48 shambhala kernel: Call Trace:
> Sep 25 21:36:48 shambhala kernel: [<c102a154>] ?
> cpuacct_charge+0x44/0x50 Sep 25 21:36:48 shambhala kernel:
> [<c125b993>] ?
> cfq_set_request+0x1a3/0x410
> Sep 25 21:36:48 shambhala kernel: [<c10a9c43>] ? 
> mempool_alloc_slab+0x13/0x20
> Sep 25 21:36:48 shambhala kernel: [<c125b7f0>] ?
> cfq_set_request+0x0/0x410 Sep 25 21:36:48 shambhala kernel:
> [<c12463f7>] ? elv_set_request+0x17/0x30 Sep 25 21:36:48 shambhala
> kernel: [<c124c95c>] ? get_request+0x31c/0x340 Sep 25 21:36:48
> shambhala kernel: [<c124c9a2>] ?
> get_request_wait+0x22/0x1a0
> Sep 25 21:36:48 shambhala kernel: [<c12f110a>] ? 
> attribute_container_add_device+0x11a/0x1e0
> Sep 25 21:36:48 shambhala kernel: [<c1268d81>] ? kvasprintf+0x41/0x50
> Sep 25 21:36:48 shambhala kernel: [<c124cfbb>] ?
> blk_get_request+0x5b/0x90 Sep 25 21:36:48 shambhala kernel:
> [<c1308998>] ? scsi_execute+0x28/0x240 Sep 25 21:36:48 shambhala
> kernel: [<c130a627>] ?
> scsi_execute_req+0x87/0x160
> Sep 25 21:36:48 shambhala kernel: [<c130bb6c>] ? 
> scsi_probe_and_add_lun+0x1ec/0x9f0
> Sep 25 21:36:48 shambhala kernel: [<c1268d81>] ? kvasprintf+0x41/0x50
> Sep 25 21:36:48 shambhala kernel: [<c12e9b24>] ?
> trace_kmalloc+0x54/0x90 Sep 25 21:36:48 shambhala kernel: [<c130c7e0>]
> ?
> __scsi_scan_target+0xe0/0x580
> Sep 25 21:36:48 shambhala kernel: [<c102a154>] ?
> cpuacct_charge+0x44/0x50 Sep 25 21:36:48 shambhala kernel:
> [<c102a154>] ? cpuacct_charge+0x44/0x50 Sep 25 21:36:48 shambhala
> kernel: [<c102e2f5>] ? update_curr+0x1b5/0x290 Sep 25 21:36:48
> shambhala kernel: [<c130cd06>] ?
> scsi_scan_channel+0x86/0xa0
> Sep 25 21:36:48 shambhala kernel: [<c130cde9>] ? 
> scsi_scan_host_selected+0xc9/0x120
> Sep 25 21:36:48 shambhala kernel: [<c130cec0>] ?
> do_scan_async+0x0/0x180 Sep 25 21:36:48 shambhala kernel: [<c130cebd>]
> ?
> do_scsi_scan_host+0x7d/0x80
> Sep 25 21:36:48 shambhala kernel: [<c130ced8>] ?
> do_scan_async+0x18/0x180 Sep 25 21:36:48 shambhala kernel:
> [<c13fa837>] ?
> preempt_schedule+0x37/0x50
> Sep 25 21:36:48 shambhala kernel: [<c130cec0>] ?
> do_scan_async+0x0/0x180 Sep 25 21:36:48 shambhala kernel: [<c10531f4>]
> ? kthread+0x74/0x80 Sep 25 21:36:48 shambhala kernel: [<c1053180>] ?
> kthread+0x0/0x80 Sep 25 21:36:48 shambhala kernel: [<c100347e>] ?
> kernel_thread_helper+0x6/0x10
> Sep 25 21:36:48 shambhala kernel: Code: e4 83 45 d8 54 83 7d e4 03 0f
> 85  ee fe ff ff 8b 03 c7 83 64 02 00 00 01 00 00 00 83 e0 03 09 d8 89
> 03 8b 45 c0 8b 90 58 01 00 00 <8b> 42 2c 85 c0 74 78 8d 55 ec 89 54 24
> 0c 8d 55 f0 89 54 24 08
> Sep 25 21:36:48 shambhala kernel: EIP: [<c125b5de>] 
> cfq_get_queue+0x33e/0x550 SS:ESP 0068:dc889c64
> Sep 25 21:36:48 shambhala kernel: CR2: 000000000000002c
> Sep 25 21:36:48 shambhala kernel: ---[ end trace eecaeed94ae31965 ]---
> Sep 25 21:36:48 shambhala kernel: note: scsi_scan_3[10474] exited with 
> preempt_count 1

This one and another one with my Silicon Image based Delock PCMCIA eSATA 
card are systemd related.

It is completely beyond me how a userspace tool could trigger these kind 
of kernel problems, but they go away when I remove init=/bin/systemd from 
kernel command line. Possibly udev initialization happens differently or 
systemd parallizes something to much.

Using

martin@shambhala:~> apt-show-versions | grep systemd
libpam-systemd/experimental uptodate 8-2
systemd/experimental uptodate 8-2
systemd-gui/experimental uptodate 8-2

I keep it at sysvinit for now, to just test one thing at a time. I will go 
on testing mainline in kernel suspend for a while, before testing Nigel's 
(possibly in the mean time updated) patches again.

I don't think the reported hang after resume before switching to Radeon 
KMS framebuffer is related, but after this one never seems to know. I might 
test this again as well.

Anyway, enough testing for now,
-- 
Martin 'Helios' Steigerwald - http://www.Lichtvoll.de
GPG: 03B0 0D6C 0040 0710 4AFA  B82F 991B EAAC A599 84C7

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [linux-pm] [PATCH] Hibernate: Implement readahead when resuming

[Nigel Cunningham]

Hi.

On 26/09/10 05:02, Martin Steigerwald wrote:
> Hi Nigel and Rafael,
>
> Am Samstag 25 September 2010 schrieb Nigel Cunningham:
>> Add support for submitting reads before they're needed. This greatly
>> improves the speed of resuming:
>>
>> From
>>
>> PM: Image read at 66 MB/s.
>>
>> to
>>
>> PM: Image read at 229 MB/s.
>>
>> ...and removes the need for the sync_read flag.
>
> So
>
> martin@shambhala:~/Computer/Shambhala/Kernel/2.6.36/tuxonice-head>  git
> branch -av | grep for-rafael
> * for-rafael                      d4e7490 Hibernate: Implement readahead
> when resuming
>    remotes/origin/for-rafael       d4e7490 Hibernate: Implement readahead
> when resuming
>
> martin@shambhala:~>  cat /proc/version
> Linux version 2.6.36-rc5-tp42-hibernate-accel-vmembase-0-00135-gd4e7490-
> dirty (martin@shambhala) (gcc version 4.4.5 20100728 (prerelease) (Debian
> 4.4.4-8) ) #1 PREEMPT Sat Sep 25 18:02:02 CEST 2010
>
> basically seems to work.
>
> But
>
>> Signed-off-by: Nigel Cunningham<nigel@tuxonice.net>
>> ---
>>   kernel/power/block_io.c |   97
>> ++++++++++++++++++++++++++++++++++++++++++++--- kernel/power/power.h
>>   |    4 --
>>   kernel/power/snapshot.c |    5 --
>>   kernel/power/swap.c     |    2 -
>>   4 files changed, 91 insertions(+), 17 deletions(-)
>>
>> diff --git a/kernel/power/block_io.c b/kernel/power/block_io.c
>> index fc2e05d..5a13f80 100644
>> --- a/kernel/power/block_io.c
>> +++ b/kernel/power/block_io.c
> [...]
>> +	if (!offset) {
>> +		printk("Offset zero - no more readahead.\n");
>> +		more_readahead = 0;
>> +		return 0;
>> +	}
>> +
>> +	printk("(1) Submitting readahead of sector %llu to page %p.\n",
>> +			offset, ra_page);
>
> and
>
>> +	if (!readahead_list_head) {
>> +		printk("No readahead left. Returning -EFAULT.\n");
>>   		return -EFAULT;
>> -	return hib_bio_read_page(offset, buf, sync);
>> +	}
>> +
>> +	printk("Waiting on readahead of page %p.\n", readahead_list_head);
>
> should be made optional - activatable via a debug switch - before this
> gets merged, cause it displays a lots of these on resuming which takes
> some time in itself.

Oh, I'm sorry. I completely forgot about that debugging code. Removed 
now. (Note that I'm rebasing and modifying this branch like a patch 
series, so you will get conflicts when you pull updates).

> I tried 5 times:
>
> - one with just kdm started worked nicely and really rather fast!
>
> - four with a full blown KDE 4.5.1 session with OpenGL compositing
>    - one seemed to hang prior to reinitializing the Radeon KMS DRM setup
>    - three other worked just fine
>
> I do not think that the hang is related to your changes, Nigel. The kernel
> remained stuck at the lower initial resolution and didn't seem to
> initialize the radeon KMS framebuffers at 1400x1050 properly. I didn't see
> this with 2.6.35 and userspace software suspend.
>
> Writing and reading seems to be way faster than with userspace software
> suspend, I didn't compare with unpatched in kernel suspend. But I do not
> seem to get any numbers printed:
>
> shambhala:~>  grep "Image read" /var/log/syslog
> shambhala:~#1>  dmesg | grep "Image read"
> shambhala:~#1>  dmesg | grep "Image writ"
> shambhala:~#1>  grep "Image writ" /var/log/syslog
> shambhala:~#1>

It uses pr_debug. Do you have CONFIG_PM_DEBUG=y?

> The machine seems to return more quickly to an usable state. Does in
> kernel suspend save larger images? I am especially surprised as I use
> compression with userspace software suspend which I thought should speed
> up writing the image. It feels that in kernel suspend with patches from
> you, Nigel, seems to outdo userspace software suspend by quite some
> margin.

All I have changed at the moment is how the image is saved. With these 
patches, swap is being allocated prior to saving the image (which 
shouldn't itself make a huge difference in speed), and the image is 
stored in a slightly different format which lets us not have to do i/o 
in batches. In addition (with this last patch), we submit the reads 
before we need them.

> I have a quite high setting for userspace software suspend image size:
>
>    1 # /etc/uswsusp.conf(8) -- Configuration file for s2disk/s2both·
>    2 resume device = /dev/sda2
>    3 compress = y
>    4 early writeout = y
>    5 image size = 1500
>    6 shutdown method = halt
>
> Still the machine crawls on resume for about 30 seconds or a minute before
> coming into a usable state. With patched in kernel suspend this wait for
> responsivity seems to have cut down to about 10-15 seconds.
>
> Please note: I didn't actually measure anything of this, this is just
> subjective impressions so far. Before measuring, I think I should disable
> those debug outputs I mentioned above ;).
>
> The ThinkPad T42 I am testing on has 2 GiB RAM. Swap is about 4 GB.
>
> No long term observations so far. I will report how it goes.
>
> Thanks,

Thank you!

Nigel

Re: [TuxOnIce-devel] [linux-pm] [PATCH] Hibernate: Implement readahead when resuming

[Nigel Cunningham]

Hi Martin.

On 26/09/10 05:58, Martin Steigerwald wrote:
> Am Samstag 25 September 2010 schrieb Martin Steigerwald:
>> Hi Nigel and Rafael,
>>
>> Am Samstag 25 September 2010 schrieb Nigel Cunningham:
>>> Add support for submitting reads before they're needed. This greatly
>>> improves the speed of resuming:
>>>
>>> From
>>>
>>> PM: Image read at 66 MB/s.
>>>
>>> to
>>>
>>> PM: Image read at 229 MB/s.
>>>
>>> ...and removes the need for the sync_read flag.
>>
>> So
>>
>> martin@shambhala:~/Computer/Shambhala/Kernel/2.6.36/tuxonice-head>  git
>> branch -av | grep for-rafael
>> * for-rafael                      d4e7490 Hibernate: Implement
>> readahead when resuming
>>    remotes/origin/for-rafael       d4e7490 Hibernate: Implement
>> readahead when resuming
> [...]
>> basically seems to work.
> [...]
>> I tried 5 times:
>>
>> - one with just kdm started worked nicely and really rather fast!
>>
>> - four with a full blown KDE 4.5.1 session with OpenGL compositing
>>    - one seemed to hang prior to reinitializing the Radeon KMS DRM setup
>>    - three other worked just fine
>>
>> I do not think that the hang is related to your changes, Nigel. The
>> kernel remained stuck at the lower initial resolution and didn't seem
>> to initialize the radeon KMS framebuffers at 1400x1050 properly. I
>> didn't see this with 2.6.35 and userspace software suspend.
>
> I am not so sure anymore.
>
> I got another one of these hangs with the 2.6.36-rc5 mentioned above. See
> IMG_3871.jpg for the exact display were it hung. I was able to switch view
> with Alt-F1 or something like that. And then got IMG_3873.jpg. But nothing
> happened anymore. Find these on:
>
> http://martin-steigerwald.de/tmp/tuxonice/hang-after-resume-with-pm-
> patches-for-rafael/
>
> I now tried in kernel suspend to disk with
>
> martin@shambhala:~>  cat /proc/version
> Linux version 2.6.35.5-tp42-vmembase-0-pm-avoid-oom-dirty
> (martin@shambhala) (gcc version 4.4.5 20100728 (prerelease) (Debian
> 4.4.4-8) ) #4 PREEMPT Sat Sep 25 13:29:53 CEST 2010
>
> which doesn't contain your patches, Nigel, for about 5 or 6 times and I
> did not see that hang.
>
> So maybe something in your patches, even if just the debug output I
> mentioned, or something in 2.6.36-rc5 triggers that hang.
>
> I will test 2.6.35.5 for a bit longer to make sure that there is no hang
> on resume prior to loading. I need to reboot this one now too, cause after
> one of the resume attempts USB stopped working with:
>
> Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device found,
> idVendor=1307, idProduct=0330
> Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device strings: Mfr=1,
> Product=2, SerialNumber=3
> Sep 25 21:36:47 shambhala kernel: usb 1-3: Product: Mass Storage Device
> Sep 25 21:36:47 shambhala kernel: usb 1-3: Manufacturer: Generic
> Sep 25 21:36:47 shambhala kernel: usb 1-3: SerialNumber: 00000000000006
> Sep 25 21:36:47 shambhala kernel: scsi3 : usb-storage 1-3:1.0
> Sep 25 21:36:48 shambhala kernel: BUG: unable to handle kernel NULL
> pointer dereference at 0000002c
> Sep 25 21:36:48 shambhala kernel: IP: [<c125b5de>]
> cfq_get_queue+0x33e/0x550
> Sep 25 21:36:48 shambhala kernel: *pde = 00000000
> Sep 25 21:36:48 shambhala kernel: Oops: 0000 [#1] PREEMPT
> Sep 25 21:36:48 shambhala kernel: last sysfs file:
> /sys/devices/pci0000:00/0000:00:1d.7/usb1/1-3/usb_device/usbdev1
> .4/uevent
> Sep 25 21:36:48 shambhala kernel: Modules linked in: microcode cn
> acpi_cpufreq mperf ppdev lp vboxnetadp cpufreq_us
> erspace cpufreq_stats cpufreq_conservative cpufreq_powersave vboxnetflt
> vboxdrv fuse tun usblp ohci_hcd usb_storage
>   usb_libusual nls_iso8859_15 nls_iso8859_1 nls_cp850 ntfs vfat msdos fat
> reiserfs isofs udf crc_itu_t smbfs pktcdvd
>   uinput radeon ttm drm_kms_helper drm i2c_algo_bit hdaps tp_smapi
> thinkpad_ec binfmt_misc dm_crypt snd_intel8x0m sn
> d_intel8x0 snd_ac97_codec ac97_bus snd_pcm_oss snd_mixer_oss snd_pcm
> ipw2200 snd_seq_dummy snd_seq_oss thinkpad_acp
> i hwmon snd_seq_midi libipw led_class snd_rawmidi rtc_cmos pcmcia
> intel_agp snd_seq_midi_event rtc_core nvram video
>   processor i2c_i801 parport_pc rtc_lib parport ac snd_seq battery button
> yenta_socket pcmcia_rsrc pcmcia_core joyde
> v output evdev agpgart snd_timer snd_seq_device snd snd_page_alloc
> cfg80211 rfkill lib80211 ipv6 autofs4 dm_mod rai
> d10 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq
> async_tx raid1 raid0 linear md_mod
> Sep 25 21:36:48 shambhala kernel: btrfs zlib_deflate crc32c libcrc32c
> usbhid uhci_hcd ehci_hcd sg usbcore sr_mod th
> ermal cdrom [last unloaded: scsi_wait_scan]
> Sep 25 21:36:48 shambhala kernel:
> Sep 25 21:36:48 shambhala kernel: Pid: 10474, comm: scsi_scan_3 Not
> tainted 2.6.35.5-tp42-vmembase-0-pm-avoid-oom-d
> irty #4 2373CXG/2373CXG
> Sep 25 21:36:48 shambhala kernel: EIP: 0060:[<c125b5de>] EFLAGS: 00010086
> CPU: 0
> Sep 25 21:36:48 shambhala kernel: EIP is at cfq_get_queue+0x33e/0x550
> Sep 25 21:36:48 shambhala kernel: EAX: f4d18a80 EBX: f5c9e000 ECX:
> 00000001 EDX: 00000000
> Sep 25 21:36:48 shambhala kernel: ESI: f5c9e108 EDI: f4976000 EBP:
> dc889cdc ESP: dc889c64
> Sep 25 21:36:48 shambhala kernel: DS: 007b ES: 007b FS: 0000 GS: 00e0 SS:
> 0068
> Sep 25 21:36:48 shambhala kernel: Process scsi_scan_3 (pid: 10474,
> ti=dc888000 task=ed8c8000 task.ti=dc888000)
> Sep 25 21:36:48 shambhala kernel: Stack:
> Sep 25 21:36:48 shambhala kernel: 00000000 dc889c7c c102a154 c1a4bfa0
> 00008010 00000010 ed8c8000 f5c9e044
> Sep 25 21:36:48 shambhala kernel:<0>  00000001 f4976020 f5c9e028 f5c9e0d0
> f4976444 01cea7c8 f4d18a80 00000030
> Sep 25 21:36:48 shambhala kernel:<0>  f49763ac f4759600 f41fbcc0 01000202
> 000000fc 00000000 00000000 00000003
> Sep 25 21:36:48 shambhala kernel: Call Trace:
> Sep 25 21:36:48 shambhala kernel: [<c102a154>] ? cpuacct_charge+0x44/0x50
> Sep 25 21:36:48 shambhala kernel: [<c125b993>] ?
> cfq_set_request+0x1a3/0x410
> Sep 25 21:36:48 shambhala kernel: [<c10a9c43>] ?
> mempool_alloc_slab+0x13/0x20
> Sep 25 21:36:48 shambhala kernel: [<c125b7f0>] ? cfq_set_request+0x0/0x410
> Sep 25 21:36:48 shambhala kernel: [<c12463f7>] ? elv_set_request+0x17/0x30
> Sep 25 21:36:48 shambhala kernel: [<c124c95c>] ? get_request+0x31c/0x340
> Sep 25 21:36:48 shambhala kernel: [<c124c9a2>] ?
> get_request_wait+0x22/0x1a0
> Sep 25 21:36:48 shambhala kernel: [<c12f110a>] ?
> attribute_container_add_device+0x11a/0x1e0
> Sep 25 21:36:48 shambhala kernel: [<c1268d81>] ? kvasprintf+0x41/0x50
> Sep 25 21:36:48 shambhala kernel: [<c124cfbb>] ? blk_get_request+0x5b/0x90
> Sep 25 21:36:48 shambhala kernel: [<c1308998>] ? scsi_execute+0x28/0x240
> Sep 25 21:36:48 shambhala kernel: [<c130a627>] ?
> scsi_execute_req+0x87/0x160
> Sep 25 21:36:48 shambhala kernel: [<c130bb6c>] ?
> scsi_probe_and_add_lun+0x1ec/0x9f0
> Sep 25 21:36:48 shambhala kernel: [<c1268d81>] ? kvasprintf+0x41/0x50
> Sep 25 21:36:48 shambhala kernel: [<c12e9b24>] ? trace_kmalloc+0x54/0x90
> Sep 25 21:36:48 shambhala kernel: [<c130c7e0>] ?
> __scsi_scan_target+0xe0/0x580
> Sep 25 21:36:48 shambhala kernel: [<c102a154>] ? cpuacct_charge+0x44/0x50
> Sep 25 21:36:48 shambhala kernel: [<c102a154>] ? cpuacct_charge+0x44/0x50
> Sep 25 21:36:48 shambhala kernel: [<c102e2f5>] ? update_curr+0x1b5/0x290
> Sep 25 21:36:48 shambhala kernel: [<c130cd06>] ?
> scsi_scan_channel+0x86/0xa0
> Sep 25 21:36:48 shambhala kernel: [<c130cde9>] ?
> scsi_scan_host_selected+0xc9/0x120
> Sep 25 21:36:48 shambhala kernel: [<c130cec0>] ? do_scan_async+0x0/0x180
> Sep 25 21:36:48 shambhala kernel: [<c130cebd>] ?
> do_scsi_scan_host+0x7d/0x80
> Sep 25 21:36:48 shambhala kernel: [<c130ced8>] ? do_scan_async+0x18/0x180
> Sep 25 21:36:48 shambhala kernel: [<c13fa837>] ?
> preempt_schedule+0x37/0x50
> Sep 25 21:36:48 shambhala kernel: [<c130cec0>] ? do_scan_async+0x0/0x180
> Sep 25 21:36:48 shambhala kernel: [<c10531f4>] ? kthread+0x74/0x80
> Sep 25 21:36:48 shambhala kernel: [<c1053180>] ? kthread+0x0/0x80
> Sep 25 21:36:48 shambhala kernel: [<c100347e>] ?
> kernel_thread_helper+0x6/0x10
> Sep 25 21:36:48 shambhala kernel: Code: e4 83 45 d8 54 83 7d e4 03 0f 85
> ee fe ff ff 8b 03 c7 83 64 02 00 00 01 00 00 00 83 e0 03 09 d8 89 03 8b 45
> c0 8b 90 58 01 00 00<8b>  42 2c 85 c0 74 78 8d 55 ec 89 54 24 0c 8d 55 f0
> 89 54 24 08
> Sep 25 21:36:48 shambhala kernel: EIP: [<c125b5de>]
> cfq_get_queue+0x33e/0x550 SS:ESP 0068:dc889c64
> Sep 25 21:36:48 shambhala kernel: CR2: 000000000000002c
> Sep 25 21:36:48 shambhala kernel: ---[ end trace eecaeed94ae31965 ]---
> Sep 25 21:36:48 shambhala kernel: note: scsi_scan_3[10474] exited with
> preempt_count 1
>
> Maybe the USB system has an powermanagement related issue that in kernel
> suspend triggers more easily than userspace software suspend? I didn't see
> this one before. But well, this is a bug I will report in
> bugzilla.kernel.org.
>
> Ciao,

Okay. Can you try without the last patch, and confirm that it's reliable 
(albeit slower) then?

Regards,

Nigel

Re: [TuxOnIce-devel] [linux-pm] [PATCH] Hibernate: Implement readahead when resuming

[Martin Steigerwald]

[-- Attachment #1: Type: Text/Plain, Size: 5314 bytes --]

Hi Nigel.

Am Samstag 25 September 2010 schrieb Nigel Cunningham:
> On 26/09/10 05:58, Martin Steigerwald wrote:
> > Am Samstag 25 September 2010 schrieb Martin Steigerwald:
> >> Hi Nigel and Rafael,
> >> 
> >> Am Samstag 25 September 2010 schrieb Nigel Cunningham:
> >>> Add support for submitting reads before they're needed. This
> >>> greatly improves the speed of resuming:
> >>> 
> >>> From
> >>> 
> >>> PM: Image read at 66 MB/s.
> >>> 
> >>> to
> >>> 
> >>> PM: Image read at 229 MB/s.
> >>> 
> >>> ...and removes the need for the sync_read flag.
> >> 
> >> So
> >> 
> >> martin@shambhala:~/Computer/Shambhala/Kernel/2.6.36/tuxonice-head> 
> >> git branch -av | grep for-rafael
> >> * for-rafael                      d4e7490 Hibernate: Implement
> >> readahead when resuming
> >> 
> >>    remotes/origin/for-rafael       d4e7490 Hibernate: Implement
> >> 
> >> readahead when resuming
> > 
> > [...]
> > 
> >> basically seems to work.
> > 
> > [...]
> > 
> >> I tried 5 times:
> >> 
> >> - one with just kdm started worked nicely and really rather fast!
> >> 
> >> - four with a full blown KDE 4.5.1 session with OpenGL compositing
> >> 
> >>    - one seemed to hang prior to reinitializing the Radeon KMS DRM
> >>    setup - three other worked just fine
> >> 
> >> I do not think that the hang is related to your changes, Nigel. The
> >> kernel remained stuck at the lower initial resolution and didn't
> >> seem to initialize the radeon KMS framebuffers at 1400x1050
> >> properly. I didn't see this with 2.6.35 and userspace software
> >> suspend.
> > 
> > I am not so sure anymore.
> > 
> > I got another one of these hangs with the 2.6.36-rc5 mentioned above.
> > See IMG_3871.jpg for the exact display were it hung. I was able to
> > switch view with Alt-F1 or something like that. And then got
> > IMG_3873.jpg. But nothing happened anymore. Find these on:
> > 
> > http://martin-steigerwald.de/tmp/tuxonice/hang-after-resume-with-pm-
> > patches-for-rafael/
> > 
> > I now tried in kernel suspend to disk with
> > 
> > martin@shambhala:~>  cat /proc/version
> > Linux version 2.6.35.5-tp42-vmembase-0-pm-avoid-oom-dirty
> > (martin@shambhala) (gcc version 4.4.5 20100728 (prerelease) (Debian
> > 4.4.4-8) ) #4 PREEMPT Sat Sep 25 13:29:53 CEST 2010
> > 
> > which doesn't contain your patches, Nigel, for about 5 or 6 times and
> > I did not see that hang.
> > 
> > So maybe something in your patches, even if just the debug output I
> > mentioned, or something in 2.6.36-rc5 triggers that hang.
> > 
> > I will test 2.6.35.5 for a bit longer to make sure that there is no
> > hang on resume prior to loading. I need to reboot this one now too,
> > cause after one of the resume attempts USB stopped working with:
> > 
> > Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device found,
> > idVendor=1307, idProduct=0330
> > Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device strings:
> > Mfr=1, Product=2, SerialNumber=3
> > Sep 25 21:36:47 shambhala kernel: usb 1-3: Product: Mass Storage
> > Device Sep 25 21:36:47 shambhala kernel: usb 1-3: Manufacturer:
> > Generic Sep 25 21:36:47 shambhala kernel: usb 1-3: SerialNumber:
> > 00000000000006 Sep 25 21:36:47 shambhala kernel: scsi3 : usb-storage
> > 1-3:1.0 Sep 25 21:36:48 shambhala kernel: BUG: unable to handle
> > kernel NULL pointer dereference at 0000002c
> > Sep 25 21:36:48 shambhala kernel: IP: [<c125b5de>]
> > cfq_get_queue+0x33e/0x550
> > Sep 25 21:36:48 shambhala kernel: *pde = 00000000
> > Sep 25 21:36:48 shambhala kernel: Oops: 0000 [#1] PREEMPT
[...]
> > exited with preempt_count 1
> > 
> > Maybe the USB system has an powermanagement related issue that in
> > kernel suspend triggers more easily than userspace software suspend?
> > I didn't see this one before. But well, this is a bug I will report
> > in
> > bugzilla.kernel.org.
> > 
> > Ciao,
> 
> Okay. Can you try without the last patch, and confirm that it's
> reliable (albeit slower) then?

Well as I told already (later on) the USB problem seems to be related to 
my testing of systemd in Debian - I do not get how this could be the case, 
but it works, when I remove init=/bin/systemd. I think I will report this 
as a kernel bug nonetheless, cause when I apply that "userspace shouldn't 
be able to let the kernel oops" paradigm then its a kernel bug.

Should I test without the readahead patch regarding whether that hang 
after resume, prior to activating Radeon KMS framebuffer is fixed as well?

I am a bit unsure on what to test next. My current thoughts are:

- Test whether 2.6.35.5 is stable with unpatched in kernel suspend. 
Currently in progress. Cause before that I only know its stable with 
userspace software suspend.

- Apply your patches on top of 2.6.35.5 and test that.
  - If that works, it appears to be a problem introduced by 2.6.36-rc5
    - Then I'd possibly test 2.6.36-rc5 with unpatched in kernel suspend.
  - If that doesn't work, it appears to be an issue with your patches
    - Then I test without readahead patch.

Tell me when you have any different suggestions.

Ciao,
-- 
Martin 'Helios' Steigerwald - http://www.Lichtvoll.de
GPG: 03B0 0D6C 0040 0710 4AFA  B82F 991B EAAC A599 84C7

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [TuxOnIce-devel] [linux-pm] [PATCH] Hibernate: Implement readahead when resuming

[Nigel Cunningham]

Hi.

On 26/09/10 08:10, Martin Steigerwald wrote:
> Hi Nigel.
>
> Am Samstag 25 September 2010 schrieb Nigel Cunningham:
>> On 26/09/10 05:58, Martin Steigerwald wrote:
>>> Am Samstag 25 September 2010 schrieb Martin Steigerwald:
>>>> Hi Nigel and Rafael,
>>>>
>>>> Am Samstag 25 September 2010 schrieb Nigel Cunningham:
>>>>> Add support for submitting reads before they're needed. This
>>>>> greatly improves the speed of resuming:
>>>>>
>>>>> From
>>>>>
>>>>> PM: Image read at 66 MB/s.
>>>>>
>>>>> to
>>>>>
>>>>> PM: Image read at 229 MB/s.
>>>>>
>>>>> ...and removes the need for the sync_read flag.
>>>>
>>>> So
>>>>
>>>> martin@shambhala:~/Computer/Shambhala/Kernel/2.6.36/tuxonice-head>
>>>> git branch -av | grep for-rafael
>>>> * for-rafael                      d4e7490 Hibernate: Implement
>>>> readahead when resuming
>>>>
>>>>     remotes/origin/for-rafael       d4e7490 Hibernate: Implement
>>>>
>>>> readahead when resuming
>>>
>>> [...]
>>>
>>>> basically seems to work.
>>>
>>> [...]
>>>
>>>> I tried 5 times:
>>>>
>>>> - one with just kdm started worked nicely and really rather fast!
>>>>
>>>> - four with a full blown KDE 4.5.1 session with OpenGL compositing
>>>>
>>>>     - one seemed to hang prior to reinitializing the Radeon KMS DRM
>>>>     setup - three other worked just fine
>>>>
>>>> I do not think that the hang is related to your changes, Nigel. The
>>>> kernel remained stuck at the lower initial resolution and didn't
>>>> seem to initialize the radeon KMS framebuffers at 1400x1050
>>>> properly. I didn't see this with 2.6.35 and userspace software
>>>> suspend.
>>>
>>> I am not so sure anymore.
>>>
>>> I got another one of these hangs with the 2.6.36-rc5 mentioned above.
>>> See IMG_3871.jpg for the exact display were it hung. I was able to
>>> switch view with Alt-F1 or something like that. And then got
>>> IMG_3873.jpg. But nothing happened anymore. Find these on:
>>>
>>> http://martin-steigerwald.de/tmp/tuxonice/hang-after-resume-with-pm-
>>> patches-for-rafael/
>>>
>>> I now tried in kernel suspend to disk with
>>>
>>> martin@shambhala:~>   cat /proc/version
>>> Linux version 2.6.35.5-tp42-vmembase-0-pm-avoid-oom-dirty
>>> (martin@shambhala) (gcc version 4.4.5 20100728 (prerelease) (Debian
>>> 4.4.4-8) ) #4 PREEMPT Sat Sep 25 13:29:53 CEST 2010
>>>
>>> which doesn't contain your patches, Nigel, for about 5 or 6 times and
>>> I did not see that hang.
>>>
>>> So maybe something in your patches, even if just the debug output I
>>> mentioned, or something in 2.6.36-rc5 triggers that hang.
>>>
>>> I will test 2.6.35.5 for a bit longer to make sure that there is no
>>> hang on resume prior to loading. I need to reboot this one now too,
>>> cause after one of the resume attempts USB stopped working with:
>>>
>>> Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device found,
>>> idVendor=1307, idProduct=0330
>>> Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device strings:
>>> Mfr=1, Product=2, SerialNumber=3
>>> Sep 25 21:36:47 shambhala kernel: usb 1-3: Product: Mass Storage
>>> Device Sep 25 21:36:47 shambhala kernel: usb 1-3: Manufacturer:
>>> Generic Sep 25 21:36:47 shambhala kernel: usb 1-3: SerialNumber:
>>> 00000000000006 Sep 25 21:36:47 shambhala kernel: scsi3 : usb-storage
>>> 1-3:1.0 Sep 25 21:36:48 shambhala kernel: BUG: unable to handle
>>> kernel NULL pointer dereference at 0000002c
>>> Sep 25 21:36:48 shambhala kernel: IP: [<c125b5de>]
>>> cfq_get_queue+0x33e/0x550
>>> Sep 25 21:36:48 shambhala kernel: *pde = 00000000
>>> Sep 25 21:36:48 shambhala kernel: Oops: 0000 [#1] PREEMPT
> [...]
>>> exited with preempt_count 1
>>>
>>> Maybe the USB system has an powermanagement related issue that in
>>> kernel suspend triggers more easily than userspace software suspend?
>>> I didn't see this one before. But well, this is a bug I will report
>>> in
>>> bugzilla.kernel.org.
>>>
>>> Ciao,
>>
>> Okay. Can you try without the last patch, and confirm that it's
>> reliable (albeit slower) then?
>
> Well as I told already (later on) the USB problem seems to be related to
> my testing of systemd in Debian - I do not get how this could be the case,
> but it works, when I remove init=/bin/systemd. I think I will report this
> as a kernel bug nonetheless, cause when I apply that "userspace shouldn't
> be able to let the kernel oops" paradigm then its a kernel bug.
>
> Should I test without the readahead patch regarding whether that hang
> after resume, prior to activating Radeon KMS framebuffer is fixed as well?

Yes, please. I only whipped up the readahead patch last night. Since 
it's single threaded, there's a lot less to go wrong compared to 
TuxOnIce, but it's still possible that there's some bug I haven't 
noticed yet. It would be good to be able to see it's definitely that patch.

> I am a bit unsure on what to test next. My current thoughts are:
>
> - Test whether 2.6.35.5 is stable with unpatched in kernel suspend.
> Currently in progress. Cause before that I only know its stable with
> userspace software suspend.
>
> - Apply your patches on top of 2.6.35.5 and test that.
>    - If that works, it appears to be a problem introduced by 2.6.36-rc5
>      - Then I'd possibly test 2.6.36-rc5 with unpatched in kernel suspend.
>    - If that doesn't work, it appears to be an issue with your patches
>      - Then I test without readahead patch.
>
> Tell me when you have any different suggestions.
>
> Ciao,

I'd start with 2.6.36-rc5 unpatched, and only fall back to 2.6.35 if 
that's unreliable.

Regards,

Nigel

Re: [TuxOnIce-devel] [linux-pm] [PATCH] Hibernate: Implement readahead when resuming

[Martin Steigerwald]

[-- Attachment #1: Type: Text/Plain, Size: 6828 bytes --]

Am Sonntag 26 September 2010 schrieb Nigel Cunningham:
> Hi.
> 
> On 26/09/10 08:10, Martin Steigerwald wrote:
> > Hi Nigel.
> > 
> > Am Samstag 25 September 2010 schrieb Nigel Cunningham:
> >> On 26/09/10 05:58, Martin Steigerwald wrote:
> >>> Am Samstag 25 September 2010 schrieb Martin Steigerwald:
> >>>> Hi Nigel and Rafael,
> >>>> 
> >>>> Am Samstag 25 September 2010 schrieb Nigel Cunningham:
> >>>>> Add support for submitting reads before they're needed. This
> >>>>> greatly improves the speed of resuming:
> >>>>> 
> >>>>> From
> >>>>> 
> >>>>> PM: Image read at 66 MB/s.
> >>>>> 
> >>>>> to
> >>>>> 
> >>>>> PM: Image read at 229 MB/s.
> >>>>> 
> >>>>> ...and removes the need for the sync_read flag.
> >>>> 
> >>>> So
> >>>> 
> >>>> martin@shambhala:~/Computer/Shambhala/Kernel/2.6.36/tuxonice-head>
> >>>> git branch -av | grep for-rafael
> >>>> * for-rafael                      d4e7490 Hibernate: Implement
> >>>> readahead when resuming
> >>>> 
> >>>>     remotes/origin/for-rafael       d4e7490 Hibernate: Implement
> >>>> 
> >>>> readahead when resuming
> >>> 
> >>> [...]
> >>> 
> >>>> basically seems to work.
> >>> 
> >>> [...]
> >>> 
> >>>> I tried 5 times:
> >>>> 
> >>>> - one with just kdm started worked nicely and really rather fast!
> >>>> 
> >>>> - four with a full blown KDE 4.5.1 session with OpenGL compositing
> >>>> 
> >>>>     - one seemed to hang prior to reinitializing the Radeon KMS
> >>>>     DRM setup - three other worked just fine
> >>>> 
> >>>> I do not think that the hang is related to your changes, Nigel.
> >>>> The kernel remained stuck at the lower initial resolution and
> >>>> didn't seem to initialize the radeon KMS framebuffers at
> >>>> 1400x1050 properly. I didn't see this with 2.6.35 and userspace
> >>>> software suspend.
> >>> 
> >>> I am not so sure anymore.
> >>> 
> >>> I got another one of these hangs with the 2.6.36-rc5 mentioned
> >>> above. See IMG_3871.jpg for the exact display were it hung. I was
> >>> able to switch view with Alt-F1 or something like that. And then
> >>> got IMG_3873.jpg. But nothing happened anymore. Find these on:
> >>> 
> >>> http://martin-steigerwald.de/tmp/tuxonice/hang-after-resume-with-pm
> >>> - patches-for-rafael/
> >>> 
> >>> I now tried in kernel suspend to disk with
> >>> 
> >>> martin@shambhala:~>   cat /proc/version
> >>> Linux version 2.6.35.5-tp42-vmembase-0-pm-avoid-oom-dirty
> >>> (martin@shambhala) (gcc version 4.4.5 20100728 (prerelease) (Debian
> >>> 4.4.4-8) ) #4 PREEMPT Sat Sep 25 13:29:53 CEST 2010
> >>> 
> >>> which doesn't contain your patches, Nigel, for about 5 or 6 times
> >>> and I did not see that hang.
> >>> 
> >>> So maybe something in your patches, even if just the debug output I
> >>> mentioned, or something in 2.6.36-rc5 triggers that hang.
> >>> 
> >>> I will test 2.6.35.5 for a bit longer to make sure that there is no
> >>> hang on resume prior to loading. I need to reboot this one now too,
> >>> cause after one of the resume attempts USB stopped working with:
> >>> 
> >>> Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device found,
> >>> idVendor=1307, idProduct=0330
> >>> Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device strings:
> >>> Mfr=1, Product=2, SerialNumber=3
> >>> Sep 25 21:36:47 shambhala kernel: usb 1-3: Product: Mass Storage
> >>> Device Sep 25 21:36:47 shambhala kernel: usb 1-3: Manufacturer:
> >>> Generic Sep 25 21:36:47 shambhala kernel: usb 1-3: SerialNumber:
> >>> 00000000000006 Sep 25 21:36:47 shambhala kernel: scsi3 :
> >>> usb-storage 1-3:1.0 Sep 25 21:36:48 shambhala kernel: BUG: unable
> >>> to handle kernel NULL pointer dereference at 0000002c
> >>> Sep 25 21:36:48 shambhala kernel: IP: [<c125b5de>]
> >>> cfq_get_queue+0x33e/0x550
> >>> Sep 25 21:36:48 shambhala kernel: *pde = 00000000
> >>> Sep 25 21:36:48 shambhala kernel: Oops: 0000 [#1] PREEMPT
> > 
> > [...]
> > 
> >>> exited with preempt_count 1
> >>> 
> >>> Maybe the USB system has an powermanagement related issue that in
> >>> kernel suspend triggers more easily than userspace software
> >>> suspend? I didn't see this one before. But well, this is a bug I
> >>> will report in
> >>> bugzilla.kernel.org.
> >>> 
> >>> Ciao,
> >> 
> >> Okay. Can you try without the last patch, and confirm that it's
> >> reliable (albeit slower) then?
> > 
> > Well as I told already (later on) the USB problem seems to be related
> > to my testing of systemd in Debian - I do not get how this could be
> > the case, but it works, when I remove init=/bin/systemd. I think I
> > will report this as a kernel bug nonetheless, cause when I apply
> > that "userspace shouldn't be able to let the kernel oops" paradigm
> > then its a kernel bug.
> > 
> > Should I test without the readahead patch regarding whether that hang
> > after resume, prior to activating Radeon KMS framebuffer is fixed as
> > well?
> 
> Yes, please. I only whipped up the readahead patch last night. Since
> it's single threaded, there's a lot less to go wrong compared to
> TuxOnIce, but it's still possible that there's some bug I haven't
> noticed yet. It would be good to be able to see it's definitely that
> patch.
> 
> > I am a bit unsure on what to test next. My current thoughts are:
> > 
> > - Test whether 2.6.35.5 is stable with unpatched in kernel suspend.
> > Currently in progress. Cause before that I only know its stable with
> > userspace software suspend.
> > 
> > - Apply your patches on top of 2.6.35.5 and test that.
> > 
> >    - If that works, it appears to be a problem introduced by
> >    2.6.36-rc5
> >    
> >      - Then I'd possibly test 2.6.36-rc5 with unpatched in kernel
> >      suspend.
> >    
> >    - If that doesn't work, it appears to be an issue with your
> >    patches
> >    
> >      - Then I test without readahead patch.
> > 
> > Tell me when you have any different suggestions.
> > 
> > Ciao,
> 
> I'd start with 2.6.36-rc5 unpatched, and only fall back to 2.6.35 if
> that's unreliable.

Done so. 2.6.36-rc5-tp42-vmembase-0-dirty without your pm patches is 
stable. So these hangs on resume seem somehow related to your patches or 
to the debug output that you left in.

Now compiling

martin@shambhala:~/Computer/Shambhala/Kernel/2.6.36/tuxonice-head> git 
branch -v 
* (no branch) 3394a84 Hibernation: Remove now-empty routines.
[...]

Which is one commit before

  for-rafael  14c1209 Hibernate: Implement readahead when resuming

I also enabled CONFIG_PM_DEBUG and CONFIG_PM_ADVANCED_DEBUG.

Tell me, when I instead should try that suspend-next stuff. ;)

Ciao,
-- 
Martin 'Helios' Steigerwald - http://www.Lichtvoll.de
GPG: 03B0 0D6C 0040 0710 4AFA  B82F 991B EAAC A599 84C7

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [TuxOnIce-devel] [linux-pm] [PATCH] Hibernate: Implement readahead when resuming

[Martin Steigerwald]

[-- Attachment #1: Type: Text/Plain, Size: 10951 bytes --]

Am Dienstag 28 September 2010 schrieb Martin Steigerwald:
> Am Sonntag 26 September 2010 schrieb Nigel Cunningham:
> > Hi.
> > 
> > On 26/09/10 08:10, Martin Steigerwald wrote:
> > > Hi Nigel.
> > > 
> > > Am Samstag 25 September 2010 schrieb Nigel Cunningham:
> > >> On 26/09/10 05:58, Martin Steigerwald wrote:
> > >>> Am Samstag 25 September 2010 schrieb Martin Steigerwald:
> > >>>> Hi Nigel and Rafael,
> > >>>> 
> > >>>> Am Samstag 25 September 2010 schrieb Nigel Cunningham:
> > >>>>> Add support for submitting reads before they're needed. This
> > >>>>> greatly improves the speed of resuming:
> > >>>>> 
> > >>>>> From
> > >>>>> 
> > >>>>> PM: Image read at 66 MB/s.
> > >>>>> 
> > >>>>> to
> > >>>>> 
> > >>>>> PM: Image read at 229 MB/s.
> > >>>>> 
> > >>>>> ...and removes the need for the sync_read flag.
> > >>>> 
> > >>>> So
> > >>>> 
> > >>>> martin@shambhala:~/Computer/Shambhala/Kernel/2.6.36/tuxonice-hea
> > >>>> d> git branch -av | grep for-rafael
> > >>>> * for-rafael                      d4e7490 Hibernate: Implement
> > >>>> readahead when resuming
> > >>>> 
> > >>>>     remotes/origin/for-rafael       d4e7490 Hibernate: Implement
> > >>>> 
> > >>>> readahead when resuming
> > >>> 
> > >>> [...]
> > >>> 
> > >>>> basically seems to work.
> > >>> 
> > >>> [...]
> > >>> 
> > >>>> I tried 5 times:
> > >>>> 
> > >>>> - one with just kdm started worked nicely and really rather
> > >>>> fast!
> > >>>> 
> > >>>> - four with a full blown KDE 4.5.1 session with OpenGL
> > >>>> compositing
> > >>>> 
> > >>>>     - one seemed to hang prior to reinitializing the Radeon KMS
> > >>>>     DRM setup - three other worked just fine
> > >>>> 
> > >>>> I do not think that the hang is related to your changes, Nigel.
> > >>>> The kernel remained stuck at the lower initial resolution and
> > >>>> didn't seem to initialize the radeon KMS framebuffers at
> > >>>> 1400x1050 properly. I didn't see this with 2.6.35 and userspace
> > >>>> software suspend.
> > >>> 
> > >>> I am not so sure anymore.
> > >>> 
> > >>> I got another one of these hangs with the 2.6.36-rc5 mentioned
> > >>> above. See IMG_3871.jpg for the exact display were it hung. I was
> > >>> able to switch view with Alt-F1 or something like that. And then
> > >>> got IMG_3873.jpg. But nothing happened anymore. Find these on:
> > >>> 
> > >>> http://martin-steigerwald.de/tmp/tuxonice/hang-after-resume-with-
> > >>> pm - patches-for-rafael/
> > >>> 
> > >>> I now tried in kernel suspend to disk with
> > >>> 
> > >>> martin@shambhala:~>   cat /proc/version
> > >>> Linux version 2.6.35.5-tp42-vmembase-0-pm-avoid-oom-dirty
> > >>> (martin@shambhala) (gcc version 4.4.5 20100728 (prerelease)
> > >>> (Debian 4.4.4-8) ) #4 PREEMPT Sat Sep 25 13:29:53 CEST 2010
> > >>> 
> > >>> which doesn't contain your patches, Nigel, for about 5 or 6 times
> > >>> and I did not see that hang.
> > >>> 
> > >>> So maybe something in your patches, even if just the debug output
> > >>> I mentioned, or something in 2.6.36-rc5 triggers that hang.
> > >>> 
> > >>> I will test 2.6.35.5 for a bit longer to make sure that there is
> > >>> no hang on resume prior to loading. I need to reboot this one
> > >>> now too, cause after one of the resume attempts USB stopped
> > >>> working with:
> > >>> 
> > >>> Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device found,
> > >>> idVendor=1307, idProduct=0330
> > >>> Sep 25 21:36:47 shambhala kernel: usb 1-3: New USB device
> > >>> strings: Mfr=1, Product=2, SerialNumber=3
> > >>> Sep 25 21:36:47 shambhala kernel: usb 1-3: Product: Mass Storage
> > >>> Device Sep 25 21:36:47 shambhala kernel: usb 1-3: Manufacturer:
> > >>> Generic Sep 25 21:36:47 shambhala kernel: usb 1-3: SerialNumber:
> > >>> 00000000000006 Sep 25 21:36:47 shambhala kernel: scsi3 :
> > >>> usb-storage 1-3:1.0 Sep 25 21:36:48 shambhala kernel: BUG: unable
> > >>> to handle kernel NULL pointer dereference at 0000002c
> > >>> Sep 25 21:36:48 shambhala kernel: IP: [<c125b5de>]
> > >>> cfq_get_queue+0x33e/0x550
> > >>> Sep 25 21:36:48 shambhala kernel: *pde = 00000000
> > >>> Sep 25 21:36:48 shambhala kernel: Oops: 0000 [#1] PREEMPT
> > > 
> > > [...]
> > > 
> > >>> exited with preempt_count 1
> > >>> 
> > >>> Maybe the USB system has an powermanagement related issue that in
> > >>> kernel suspend triggers more easily than userspace software
> > >>> suspend? I didn't see this one before. But well, this is a bug I
> > >>> will report in
> > >>> bugzilla.kernel.org.
> > >>> 
> > >>> Ciao,
> > >> 
> > >> Okay. Can you try without the last patch, and confirm that it's
> > >> reliable (albeit slower) then?
> > > 
> > > Well as I told already (later on) the USB problem seems to be
> > > related to my testing of systemd in Debian - I do not get how this
> > > could be the case, but it works, when I remove init=/bin/systemd.
> > > I think I will report this as a kernel bug nonetheless, cause when
> > > I apply that "userspace shouldn't be able to let the kernel oops"
> > > paradigm then its a kernel bug.
> > > 
> > > Should I test without the readahead patch regarding whether that
> > > hang after resume, prior to activating Radeon KMS framebuffer is
> > > fixed as well?
> > 
> > Yes, please. I only whipped up the readahead patch last night. Since
> > it's single threaded, there's a lot less to go wrong compared to
> > TuxOnIce, but it's still possible that there's some bug I haven't
> > noticed yet. It would be good to be able to see it's definitely that
> > patch.
> > 
> > > I am a bit unsure on what to test next. My current thoughts are:
> > > 
> > > - Test whether 2.6.35.5 is stable with unpatched in kernel suspend.
> > > Currently in progress. Cause before that I only know its stable
> > > with userspace software suspend.
> > > 
> > > - Apply your patches on top of 2.6.35.5 and test that.
> > > 
> > >    - If that works, it appears to be a problem introduced by
> > >    2.6.36-rc5
> > >    
> > >      - Then I'd possibly test 2.6.36-rc5 with unpatched in kernel
> > >      suspend.
> > >    
> > >    - If that doesn't work, it appears to be an issue with your
> > >    patches
> > >    
> > >      - Then I test without readahead patch.
> > > 
> > > Tell me when you have any different suggestions.
> > > 
> > > Ciao,
> > 
> > I'd start with 2.6.36-rc5 unpatched, and only fall back to 2.6.35 if
> > that's unreliable.
> 
> Done so. 2.6.36-rc5-tp42-vmembase-0-dirty without your pm patches is
> stable. So these hangs on resume seem somehow related to your patches
> or to the debug output that you left in.
> 
> Now compiling
> 
> martin@shambhala:~/Computer/Shambhala/Kernel/2.6.36/tuxonice-head> git
> branch -v
> * (no branch) 3394a84 Hibernation: Remove now-empty routines.
> [...]
> 
> Which is one commit before
> 
>   for-rafael  14c1209 Hibernate: Implement readahead when resuming
> 
> I also enabled CONFIG_PM_DEBUG and CONFIG_PM_ADVANCED_DEBUG.
> 
> Tell me, when I instead should try that suspend-next stuff. ;)

Done six cycles, so far so good:

shambhala:~> grep "PM: Image.*at " /var/log/syslog
Sep 28 11:32:06 shambhala kernel: PM: Image written at 63 MB/s.
Sep 28 11:32:06 shambhala kernel: PM: Image read at 32 MB/s.
Sep 28 11:35:00 shambhala kernel: PM: Image written at 65 MB/s.
Sep 28 11:35:00 shambhala kernel: PM: Image read at 32 MB/s.
Sep 28 11:38:43 shambhala kernel: PM: Image written at 65 MB/s.
Sep 28 11:38:43 shambhala kernel: PM: Image read at 33 MB/s.
Sep 28 11:41:15 shambhala kernel: PM: Image written at 66 MB/s.
Sep 28 11:41:15 shambhala kernel: PM: Image read at 33 MB/s.
Sep 28 11:42:57 shambhala kernel: PM: Image written at 66 MB/s.
Sep 28 11:42:57 shambhala kernel: PM: Image read at 34 MB/s.
Sep 28 11:45:16 shambhala kernel: PM: Image written at 66 MB/s.
Sep 28 11:45:16 shambhala kernel: PM: Image read at 34 MB/s.

I think I will keep 2.6.36-rc5-tp42-hiber-wri-accel-vmembase-0-00133-
g3394a84-dirty (for-rafael minus readahead patch) at least till tomorrow 
for some longer term testing. Read obviously is not sped up so far.

You get my Tested-By line when that kernel works till tomorrow or so ;).

What next to test? suspend-next?

Last attempts with (currently not reproducably stably working) TuxOnIce:

Sep  9 01:04:22 shambhala kernel: TuxOnIce debugging info:
Sep  9 01:04:22 shambhala kernel: - TuxOnIce core  : 3.2-rc2
Sep  9 01:04:22 shambhala kernel: - Kernel Version : 2.6.36-rc3-tp42-
toi-3.2-rc1-vmembase-0-05032-g60140c1-dirty
Sep  9 01:04:22 shambhala kernel: - Compiler vers. : 4.4
Sep  9 01:04:22 shambhala kernel: - Attempt number : 1
Sep  9 01:04:22 shambhala kernel: - Parameters     : 0 667656 0 1 900 0
Sep  9 01:04:22 shambhala kernel: - Overall expected compression 
percentage: 50.
Sep  9 01:04:22 shambhala kernel: - Checksum method is 'md4'.
Sep  9 01:04:22 shambhala kernel:  0 pages resaved in atomic copy.
Sep  9 01:04:22 shambhala kernel: - Compressor is 'lzo'.
Sep  9 01:04:22 shambhala kernel:  Compressed 923176960 bytes into 
393309240 (57 percent compression).
Sep  9 01:04:22 shambhala kernel: - Block I/O active.
Sep  9 01:04:22 shambhala kernel:  Used 96698 pages from swap on 
/dev/sda2.
Sep  9 01:04:22 shambhala kernel: - Max outstanding reads 1620. Max writes 
9.
Sep  9 01:04:22 shambhala kernel:  Memory_needed: 1024 x (4096 + 220 + 76) 
= 4497408 bytes.
Sep  9 01:04:22 shambhala kernel:  Free mem throttle point reached 0.
Sep  9 01:04:22 shambhala kernel: - Swap Allocator enabled.
Sep  9 01:04:22 shambhala kernel:  Swap available for image: 1234586 
pages.
Sep  9 01:04:22 shambhala kernel: - File Allocator active.
Sep  9 01:04:22 shambhala kernel:  Storage available for image: 0 pages.
Sep  9 01:04:22 shambhala kernel: - I/O speed: Write 50 MB/s, Read 98 
MB/s.
Sep  9 01:04:22 shambhala kernel: - Extra pages    : 11320 used/20000.
Sep  9 01:04:22 shambhala kernel: - Result         : Succeeded.

shambhala:~> zgrep "I/O speed" /var/log/syslog.3.gz
Sep  9 01:04:22 shambhala kernel: - I/O speed: Write 50 MB/s, Read 98 
MB/s.
Sep  9 10:22:58 shambhala kernel: - I/O speed: Write 49 MB/s, Read 98 
MB/s.
Sep 10 10:21:20 shambhala kernel: - I/O speed: Write 47 MB/s, Read 99 
MB/s.
Sep 11 10:19:52 shambhala kernel: - I/O speed: Write 49 MB/s, Read 100 
MB/s.
Sep 11 16:54:56 shambhala kernel: - I/O speed: Write 46 MB/s, Read 93 
MB/s.

So in-kernel-suspend actually seems to write faster, but TuxOnIce had lzo 
compressor active. For compression it would be nice to have two stats: 
Reading / writing compressed as well as uncompressed data? Cause 50 MiB/s 
compressed data might equal or even exceed 66 MiB/s uncompressed data. 

Thanks,
-- 
Martin 'Helios' Steigerwald - http://www.Lichtvoll.de
GPG: 03B0 0D6C 0040 0710 4AFA  B82F 991B EAAC A599 84C7

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: [linux-pm] [TuxOnIce-devel] [PATCH] Hibernate: Implement readahead when resuming

[Bojan Smojver]

On Tue, 2010-09-28 at 11:56 +0200, Martin Steigerwald wrote:
> So in-kernel-suspend actually seems to write faster, but TuxOnIce had
> lzo compressor active. 

If you used recent versions of Rafael's tree, this will have LZO as
well. Just look at kernel/power/swap.c. If it has lzo.h there, it's
being used (unless you told it not to).

-- 
Bojan

Re: [PATCH] Hibernate: Implement readahead when resuming

[Pavel Machek]

Hi!

> Add support for submitting reads before they're needed. This greatly
> improves the speed of resuming:
> 
> From
> 
> PM: Image read at 66 MB/s.
> 
> to
> 
> PM: Image read at 229 MB/s.
> 
> ...and removes the need for the sync_read flag.

Hmm, not bad.

> @@ -67,13 +70,14 @@ static void hib_end_bio(struct bio *bio, int err)
>   *	@off	physical offset of page.
>   *	@page:	page we're reading or writing.
>   *	@sync:	whether the i/o should be done synchronously
> + *	@ra:	whether the page is readahead
>   *

This sync flag?

Merge sync and ra into 'flags' to make code easier to read?

>   *	Straight from the textbook - allocate and initialize the bio.
>   *	If we're reading, make sure the page is marked as dirty.
>   *	Then submit it and, if @sync, wait.
>   */
>  static int submit(int rw, struct block_device *bdev, sector_t sector,
> -		struct page *page, int sync)
> +		struct page *page, int sync, int ra)
>  {
>  	const int bio_rw = rw | REQ_SYNC | REQ_UNPLUG;
>  	struct bio *bio;

> +	printk("(1) Submitting readahead of sector %llu to page %p.\n",
> +			offset, ra_page);

KERN_INFO?

> +	return submit(READ, hib_resume_bdev, offset * (PAGE_SIZE >> 9),
> +			ra_page, 0, 1);
> +}
> +
> +int start_more_readahead(void)

Too generic name for global function?

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html