The patchset adds compression support to pstore.
As the non-volatile storage space is limited, adding compression
support results in capturing more data within limited space.
Size of dmesg file in a powerpc/pseries box with nvram's
oops partition (to store oops-log) size 4k:
Without compression:
dmesg-nvram-1: ~ 4k (3980)
WIth compression:
dmesg-nvram-1: ~8.8k (8844)
Writing to persistent store
----------------------------
Compression will reduce the size of oops/panic report to atmost 45% of its
original size. (Based on experiments done while providing compression support
to nvram by Jim keniston).
Hence buffer of size ( (100/45 approx 2.22) *<registered_buffer> is allocated).
The compression parameters selected based on some experiments:
compression_level = 6, window_bits = 12, memory_level = 4 which achieved a
significant compression of 12 % of uncompressed buffer size tried upto 36k.
Data is compressed from the bigger buffer to registered buffer which is
returned to backends.
Pstore will indicate that with a flag 'compressed' which is passed to backends.
Using this flag, backends will add a flag in their header to indicate the data
is compressed or not while writing to persistent store.
Reading from persistent store
-----------------------------
When backends read data from persistent store it will use the flag added by it
while writing to persistent store to determine if the data is compressed or not.
Using the information, it will set the flag in pstore's read call back.
Pstore will decompress the data based on the flag and writes decompressed data
to the file.
Test results:
Have tested the patches on powerpc/pseries.
On Intel have only tested with erst backend.
Efi-pstore and RAM persistent buffer requires testing.
---
Aruna Balakrishnaiah (11):
powerpc/pseries: Remove (de)compression in nvram with pstore enabled
pstore: Add new argument 'compressed' in pstore write callback
pstore/Kconfig: Select ZLIB_DEFLATE and ZLIB_INFLATE when PSTORE is selected
pstore: Add compression support to pstore
pstore: Introduce new argument 'compressed' in the read callback
pstore: Provide decompression support to pstore
pstore: Add file extension to pstore file if compressed
powerpc/pseries: Read and write to the 'compressed' flag of pstore
erst: Read and write to the 'compressed' flag of pstore
efi-pstore: Read and write to the 'compressed' flag of pstore
pstore/ram: Read and write to the 'compressed' flag of pstore
arch/powerpc/platforms/pseries/nvram.c | 131 ++++----------------
drivers/acpi/apei/erst.c | 21 ++-
drivers/firmware/efi/efi-pstore.c | 27 +++-
fs/pstore/Kconfig | 2
fs/pstore/inode.c | 9 +
fs/pstore/internal.h | 5 -
fs/pstore/platform.c | 214 ++++++++++++++++++++++++++++++--
fs/pstore/ram.c | 41 +++++-
include/linux/pstore.h | 6 -
9 files changed, 307 insertions(+), 149 deletions(-)
--
(De)compression support is provided in pstore in subsequent patches which
needs an additional argument 'compressed' to determine if the data
is compressed or not. This patch will take care of removing (de)compression
in nvram with pstore which was making use of 'hsize' argument in pstore write
as 'hsize' will be removed in the subsequent patch.
Signed-off-by: Aruna Balakrishnaiah <redacted>
---
arch/powerpc/platforms/pseries/nvram.c | 40 --------------------------------
1 file changed, 40 deletions(-)
Addition of new argument 'compressed' in the write call back will
help the backend to know if the data passed from pstore is compressed
or not (In case where compression fails.). If compressed, the backend
can add a tag indicating the data is compressed while writing to
persistent store.
Signed-off-by: Aruna Balakrishnaiah <redacted>
---
arch/powerpc/platforms/pseries/nvram.c | 4 ++--
drivers/acpi/apei/erst.c | 4 ++--
drivers/firmware/efi/efi-pstore.c | 2 +-
fs/pstore/platform.c | 7 ++++---
fs/pstore/ram.c | 2 +-
include/linux/pstore.h | 4 ++--
6 files changed, 12 insertions(+), 11 deletions(-)
Pstore will make use of deflate and inflate algorithm to compress and decompress
the data. So when Pstore is enabled select zlib_deflate and zlib_inflate.
Signed-off-by: Aruna Balakrishnaiah <redacted>
---
fs/pstore/Kconfig | 2 ++
1 file changed, 2 insertions(+)
Add compression support to pstore which will help in capturing more data.
Initially, pstore will make a call to kmsg_dump with a bigger buffer
and will pass the size of bigger buffer to kmsg_dump and then compress
the data to registered buffer of registered size.
In case compression fails, pstore will capture the uncompressed
data by making a call again to kmsg_dump with registered_buffer
of registered size.
Pstore will indicate the data is compressed or not with a flag
in the write callback.
Signed-off-by: Aruna Balakrishnaiah <redacted>
---
fs/pstore/platform.c | 124 ++++++++++++++++++++++++++++++++++++++++++++++----
1 file changed, 115 insertions(+), 9 deletions(-)
@@ -65,6 +66,12 @@ struct pstore_info *psinfo;staticchar*backend;+/* Compression parameters */+#define COMPR_LEVEL 6+#define WINDOW_BITS 12+#define MEM_LEVEL 4+staticstructz_stream_sstream;+/* How much of the console log to snapshot */staticunsignedlongkmsg_bytes=10240;
@@ -117,6 +124,80 @@ bool pstore_cannot_block_path(enum kmsg_dump_reason reason)}EXPORT_SYMBOL_GPL(pstore_cannot_block_path);+/* Derived from logfs_compress() */+staticintpstore_compress(constvoid*in,void*out,size_tinlen,+size_toutlen)+{+interr,ret;++ret=-EIO;+err=zlib_deflateInit2(&stream,COMPR_LEVEL,Z_DEFLATED,WINDOW_BITS,+MEM_LEVEL,Z_DEFAULT_STRATEGY);+if(err!=Z_OK)+gotoerror;++stream.next_in=in;+stream.avail_in=inlen;+stream.total_in=0;+stream.next_out=out;+stream.avail_out=outlen;+stream.total_out=0;++err=zlib_deflate(&stream,Z_FINISH);+if(err!=Z_STREAM_END)+gotoerror;++err=zlib_deflateEnd(&stream);+if(err!=Z_OK)+gotoerror;++if(stream.total_out>=stream.total_in)+gotoerror;++ret=stream.total_out;+error:+returnret;+}++/* Compress the text from dst into psinfo->buf. */+staticintzip_data(char*dst,size_ttext_len)+{+intzipped_len=pstore_compress(dst,psinfo->buf,text_len,+psinfo->bufsize);++kfree(dst);+kfree(stream.workspace);+if(zipped_len<0){+pr_err("pstore: compression failed; returned %d\n",zipped_len);+pr_err("pstore: logging uncompressed oops/panic report\n");+return-1;+}++returnzipped_len;+}++staticchar*allocate_buf_for_compression(unsignedlongbig_buf_sz)+{+char*big_buf;++big_buf=kmalloc(big_buf_sz,GFP_KERNEL);+if(big_buf){+stream.workspace=kmalloc(zlib_deflate_workspacesize(+WINDOW_BITS,MEM_LEVEL),GFP_KERNEL);+if(!stream.workspace){+pr_err("pstore: No memory for compression workspace; "+"skipping compression\n");+kfree(big_buf);+big_buf=NULL;+}+}else{+pr_err("No memory for uncompressed data; "+"skipping compression\n");+stream.workspace=NULL;+}++returnbig_buf;+}/**callbackfromkmsg_dump.(s2,l2)hasthemostrecently*writtenbytes,olderbytesarein(s1,l1).Saveasmuch
Backends will set the flag 'compressed' after reading the log from
persistent store to indicate the data being returned to pstore is
compressed or not.
Signed-off-by: Aruna Balakrishnaiah <redacted>
---
arch/powerpc/platforms/pseries/nvram.c | 2 +-
drivers/acpi/apei/erst.c | 4 ++--
drivers/firmware/efi/efi-pstore.c | 3 ++-
fs/pstore/platform.c | 4 +++-
fs/pstore/ram.c | 3 ++-
include/linux/pstore.h | 2 +-
6 files changed, 11 insertions(+), 7 deletions(-)
Based on the flag 'compressed' set or not, pstore will decompress the
data returning a plain text file. If decompression fails for a particular
record it will have the compressed data in the file which can be
decompressed with 'openssl' command line tool.
Signed-off-by: Aruna Balakrishnaiah <redacted>
---
arch/powerpc/platforms/pseries/nvram.c | 59 -------------------------
fs/pstore/platform.c | 77 ++++++++++++++++++++++++++++++++
2 files changed, 76 insertions(+), 60 deletions(-)
@@ -539,65 +539,6 @@ static int zip_oops(size_t text_len)}#ifdef CONFIG_PSTORE-/* Derived from logfs_uncompress */-intnvram_decompress(void*in,void*out,size_tinlen,size_toutlen)-{-interr,ret;--ret=-EIO;-err=zlib_inflateInit(&stream);-if(err!=Z_OK)-gotoerror;--stream.next_in=in;-stream.avail_in=inlen;-stream.total_in=0;-stream.next_out=out;-stream.avail_out=outlen;-stream.total_out=0;--err=zlib_inflate(&stream,Z_FINISH);-if(err!=Z_STREAM_END)-gotoerror;--err=zlib_inflateEnd(&stream);-if(err!=Z_OK)-gotoerror;--ret=stream.total_out;-error:-returnret;-}--staticintunzip_oops(char*oops_buf,char*big_buf)-{-structoops_log_info*oops_hdr=(structoops_log_info*)oops_buf;-u64timestamp=oops_hdr->timestamp;-char*big_oops_data=NULL;-char*oops_data_buf=NULL;-size_tbig_oops_data_sz;-intunzipped_len;--big_oops_data=big_buf+sizeof(structoops_log_info);-big_oops_data_sz=big_oops_buf_sz-sizeof(structoops_log_info);-oops_data_buf=oops_buf+sizeof(structoops_log_info);--unzipped_len=nvram_decompress(oops_data_buf,big_oops_data,-oops_hdr->report_length,-big_oops_data_sz);--if(unzipped_len<0){-pr_err("nvram: decompression failed; returned %d\n",-unzipped_len);-return-1;-}-oops_hdr=(structoops_log_info*)big_buf;-oops_hdr->version=OOPS_HDR_VERSION;-oops_hdr->report_length=(u16)unzipped_len;-oops_hdr->timestamp=timestamp;-return0;-}-staticintnvram_pstore_open(structpstore_info*psi){/* Reset the iterator to start reading partitions again */
In case decompression fails, add a ".enc.z" to indicate the file has
compressed data. This will help user space utilities to figure
out the file contents.
Signed-off-by: Aruna Balakrishnaiah <redacted>
---
fs/pstore/inode.c | 9 +++++----
fs/pstore/internal.h | 5 +++--
fs/pstore/platform.c | 4 +++-
3 files changed, 11 insertions(+), 7 deletions(-)
If data returned from pstore is compressed, nvram's write callback
will add a flag ERR_TYPE_KERNEL_PANIC_GZ indicating the data is compressed
while writing to nvram. If the data read from nvram is compressed, nvram's
read callback will set the flag 'compressed'. The patch adds backward
compatibilty with old format oops header when reading from pstore.
Signed-off-by: Aruna Balakrishnaiah <redacted>
---
arch/powerpc/platforms/pseries/nvram.c | 34 +++++++++++++++++++++++++-------
1 file changed, 27 insertions(+), 7 deletions(-)
@@ -669,14 +671,32 @@ read_partition:*id=id_no;if(nvram_type_ids[read_type]==PSTORE_TYPE_DMESG){+u16length;oops_hdr=(structoops_log_info*)buff;-*buf=buff+sizeof(*oops_hdr);-time->tv_sec=oops_hdr->timestamp;-time->tv_nsec=0;-returnoops_hdr->report_length;++/* Provide backward compatibility with old format headers */+if(oops_hdr->version<OOPS_HDR_VERSION){+*buf=buff+sizeof(u16);+length=oops_hdr->version;+time->tv_sec=0;+time->tv_nsec=0;+}else{+*buf=buff+sizeof(*oops_hdr);+length=oops_hdr->report_length;+time->tv_sec=oops_hdr->timestamp;+time->tv_nsec=0;+}++if(err_type==ERR_TYPE_KERNEL_PANIC_GZ)+*compressed=true;+else+*compressed=false;++returnlength;}*buf=buff;+*compressed=false;returnpart->size;}
In pstore write, set the section type to CPER_SECTION_TYPE_DMESG_COMPR
if the data is compressed. In pstore read, read the section type and
update the 'compressed' flag accordingly.
Signed-off-by: Aruna Balakrishnaiah <redacted>
---
drivers/acpi/apei/erst.c | 13 ++++++++++++-
1 file changed, 12 insertions(+), 1 deletion(-)
In pstore write, Efi will add a character 'C'(compressed) or
D'(decompressed) in its header while writing to persistent store.
In pstore read, read the header and update the 'compressed' flag
accordingly.
Signed-off-by: Aruna Balakrishnaiah <redacted>
---
drivers/firmware/efi/efi-pstore.c | 22 ++++++++++++++++++----
1 file changed, 18 insertions(+), 4 deletions(-)
In pstore write, add character 'C'(compressed) or 'D'(decompressed)
in the header while writing to Ram persistent buffer. In pstore read,
read the header and update the 'compressed' flag accordingly.
Signed-off-by: Aruna Balakrishnaiah <redacted>
---
fs/pstore/ram.c | 36 ++++++++++++++++++++++++++++--------
1 file changed, 28 insertions(+), 8 deletions(-)
Hi Tony/Kees,
Could you please review and let me know your comments!!
Regards,
Aruna
On Monday 15 July 2013 10:25 PM, Aruna Balakrishnaiah wrote:
The patchset adds compression support to pstore.
As the non-volatile storage space is limited, adding compression
support results in capturing more data within limited space.
Size of dmesg file in a powerpc/pseries box with nvram's
oops partition (to store oops-log) size 4k:
Without compression:
dmesg-nvram-1: ~ 4k (3980)
WIth compression:
dmesg-nvram-1: ~8.8k (8844)
Writing to persistent store
----------------------------
Compression will reduce the size of oops/panic report to atmost 45% of its
original size. (Based on experiments done while providing compression support
to nvram by Jim keniston).
Hence buffer of size ( (100/45 approx 2.22) *<registered_buffer> is allocated).
The compression parameters selected based on some experiments:
compression_level = 6, window_bits = 12, memory_level = 4 which achieved a
significant compression of 12 % of uncompressed buffer size tried upto 36k.
Data is compressed from the bigger buffer to registered buffer which is
returned to backends.
Pstore will indicate that with a flag 'compressed' which is passed to backends.
Using this flag, backends will add a flag in their header to indicate the data
is compressed or not while writing to persistent store.
Reading from persistent store
-----------------------------
When backends read data from persistent store it will use the flag added by it
while writing to persistent store to determine if the data is compressed or not.
Using the information, it will set the flag in pstore's read call back.
Pstore will decompress the data based on the flag and writes decompressed data
to the file.
Test results:
Have tested the patches on powerpc/pseries.
On Intel have only tested with erst backend.
Efi-pstore and RAM persistent buffer requires testing.
---
Aruna Balakrishnaiah (11):
powerpc/pseries: Remove (de)compression in nvram with pstore enabled
pstore: Add new argument 'compressed' in pstore write callback
pstore/Kconfig: Select ZLIB_DEFLATE and ZLIB_INFLATE when PSTORE is selected
pstore: Add compression support to pstore
pstore: Introduce new argument 'compressed' in the read callback
pstore: Provide decompression support to pstore
pstore: Add file extension to pstore file if compressed
powerpc/pseries: Read and write to the 'compressed' flag of pstore
erst: Read and write to the 'compressed' flag of pstore
efi-pstore: Read and write to the 'compressed' flag of pstore
pstore/ram: Read and write to the 'compressed' flag of pstore
arch/powerpc/platforms/pseries/nvram.c | 131 ++++----------------
drivers/acpi/apei/erst.c | 21 ++-
drivers/firmware/efi/efi-pstore.c | 27 +++-
fs/pstore/Kconfig | 2
fs/pstore/inode.c | 9 +
fs/pstore/internal.h | 5 -
fs/pstore/platform.c | 214 ++++++++++++++++++++++++++++++--
fs/pstore/ram.c | 41 +++++-
include/linux/pstore.h | 6 -
9 files changed, 307 insertions(+), 149 deletions(-)
Could you please review and let me know your comments!!
Skimmed through it today and didn't notice anything I hated. It built fine=
- but doesn't seem to be working on top of ERST. This doesn't seem to be =
your fault though, when I rebuilt a plain 3.11-rc3 it didn't log anything v=
ia pstore either :-(
Will dig some more at it tomorrow.
-Tony
From: Tony Luck <hidden> Date: 2013-08-02 21:39:58
On Thu, Aug 1, 2013 at 4:42 PM, Luck, Tony [off-list ref] wrote:
when I rebuilt a plain 3.11-rc3 it didn't log anything via pstore either :-(
Well this turned out to be operator error on my part. 3.11-rc3 does in fact
log errors to pstore and allows them to be retrieved and cleared.
So then I start testing with your 11 patches in place.
First boot was fine - ERST had no records, and pstore mounted OK
(and showed no files).
Then I panic'd the machine and rebooted. The boot hung when some
rc script printed"
Mounting other filesystems:
I guess something went wrong when pstore found a non-empty ERST.
I added some debug traces and booted again. This time the boot succeeded
but I saw a GP fault reported from pstore_mkfile(). Possibly in this code:
spin_lock_irqsave(&allpstore_lock, flags);
list_for_each_entry(pos, &allpstore, list) {
if (pos->type == type &&
pos->id == id &&
pos->psi == psi) {
rc = -EEXIST;
break;
}
}
spin_unlock_irqrestore(&allpstore_lock, flags);
My other tracing showed that we'd already found two compressed entries in
ERST and were working on a third when this error happened (implying that
my hang had been a panic that failed to print anything to console)
I've attached one of the compressed files that v3.11-rc3 shows in pstore
now. The "openssl zlib -d" trick you mentioned back in June mostly works
to decode ... but it seems to dump some trailing garbage at the end of
the file.
-Tony
From: Tony Luck <hidden> Date: 2013-08-02 22:12:40
A quick experiment to use your patchset - but with compression
disabled by tweaking this line in pstore_dump():
zipped_len = -1; //zip_data(dst, hsize + len);
turned out well. This kernel dumps uncompressed dmesg blobs into pstore
and gets them back out again. So it seems likely that the problems are
someplace in the compression/decompression code.
-Tony
From: Tony Luck <hidden> Date: 2013-08-05 16:41:18
One more experiment - removed previous hack that disabled compression.
Added a new hack to skip decompression.
System died cleanly when I forced a panic.
On reboot I found 3 files in pstore:
-r--r--r-- 1 root root 3972 Aug 5 09:24 dmesg-erst-5908671953186586625
-r--r--r-- 1 root root 2565 Aug 5 09:24 dmesg-erst-5908671953186586626
-r--r--r-- 1 root root 4067 Aug 5 09:24 dmesg-erst-5908671953186586627
Using "openssl zlib -d" to decompress then ends up with some garbage
at the end of the decompressed file - some text that should be there is
missing. E.g. the tail of decompressed version of *625 ends with:
<4>Call Trace:
<4> [<ffffffff815f85f4>] dump_stack+0x45/0x56
<4> [<ffffffff815f41ca>] panic+0xc2/0x1cb
<4> [<ffffffff815f4327>] ? printk+0x54/0x56
<4> [<ffffffff811cfe45>] aegl+0x25/0x30
<4> [<ffffffff811c719d>] proc_reg_write+0x3d/0x80
<4> [<ffffffff81165945>] vfs_write+0xc5/0x1e0
<4> [<ffffffff81165e32>] SyS_write+0x52/0xa0
<4> [<ffffffff81606882>] system_call_fastpath+0x16/0x1b
)c10^@^@^@^@^@^@^@^@^@
But my serial console logged this:
Call Trace:
[<ffffffff815f85f4>] dump_stack+0x45/0x56
[<ffffffff815f41ca>] panic+0xc2/0x1cb
[<ffffffff815f4327>] ? printk+0x54/0x56
[<ffffffff811cfe45>] aegl+0x25/0x30
[<ffffffff811c719d>] proc_reg_write+0x3d/0x80
[<ffffffff81165945>] vfs_write+0xc5/0x1e0
[<ffffffff81165e32>] SyS_write+0x52/0xa0
[<ffffffff81606882>] system_call_fastpath+0x16/0x1b
------------[ cut here ]------------
WARNING: CPU: 18 PID: 381 at arch/x86/kernel/smp.c:124
native_smp_send_reschedule+0x5b/0x60()
Modules linked in:
CPU: 18 PID: 381 Comm: kworker/18:1 Not tainted 3.11.0-rc3-11-ge41db9e #6
-Tony
Hi Tony,
Thank you very much for testing my patches.
On Saturday 03 August 2013 03:42 AM, Tony Luck wrote:
A quick experiment to use your patchset - but with compression
disabled by tweaking this line in pstore_dump():
zipped_len = -1; //zip_data(dst, hsize + len);
turned out well. This kernel dumps uncompressed dmesg blobs into pstore
and gets them back out again. So it seems likely that the problems are
someplace in the compression/decompression code.
A quick look on my code suggests that problem could be in this part
of code.
In pstore_dump:
if (zipped_len < 0) {
dst = psinfo->buf;
hsize = sprintf(dst, "%s#%d Part%d\n",
why, oopscount, part);
size = psinfo->bufsize - hsize;
dst += hsize;
compressed = false;
if (!kmsg_dump_get_buffer(dumper, true, dst,
size, &len))
break;
} else {
compressed = true;
---> len = zipped_len;
}
I am returning zipped_len as the length of the compressed data (which also
has hsize compressed). So returning hsize + len in pstore_write callback
will be wrong. It should just have been zipped_len. This might be adding
junk characters.
Can you please replace this hunk with:
if (zipped_len < 0) {
pr_err("Compression failed\n");
dst = psinfo->buf;
hsize = sprintf(dst, "%s#%d Part%d\n",
why, oopscount, part);
size = psinfo->bufsize - hsize;
dst += hsize;
compressed = false;
if (!kmsg_dump_get_buffer(dumper, true, dst,
size, &len))
break;
total_len = hsize + len;
} else {
compressed = true;
total_len = zipped_len;
}
ret = psinfo->write(PSTORE_TYPE_DMESG, reason, &id, part,
oopscount, compressed, total_len, psinfo);
if (ret == 0 && reason == KMSG_DUMP_OOPS && pstore_is_mounted())
pstore_new_entry = 1;
total += total_len;
part++;
With the above hunk, atleast I dont see junk characters at the end in power.
I apologise, since I do not have the suitable machine to test this I am
not able to reproduce the scenarios you are stating. I need your help
in testing this.
- Aruna
Hi Tony,
On Monday 05 August 2013 11:52 PM, Tony Luck wrote:
See attachment for what I actually applied - I think I got what you
suggested (I added a declaration for "total_len").
Forcing a panic worked some things were logged to pstore.
But on reboot with your patches applied I'm still seeing a GP fault
when pstore is mounted and we find compressed records and inflate them
and install them into the pstore filesystem. Here's the oops:
general protection fault: 0000 [#1] SMP
Modules linked in:
CPU: 29 PID: 10252 Comm: mount Not tainted 3.11.0-rc3-12-g73bec18 #2
Hardware name: Intel Corporation LH Pass ........../SVRBD-ROW_T, BIOS
SE5C600.86B.99.99.x059.091020121352 09/10/2012
task: ffff88082e934040 ti: ffff88082e2ec000 task.ti: ffff88082e2ec000
RIP: 0010:[<ffffffff8126d314>] [<ffffffff8126d314>] pstore_mkfile+0x84/0x410
RSP: 0018:ffff88082e2edc70 EFLAGS: 00010007
RAX: 0000000000000246 RBX: ffffffff81ca7b20 RCX: 625f6963703e373c
RDX: 0000000000040004 RSI: 0000000000000004 RDI: ffffffff820aa7e8
RBP: ffff88082e2edd10 R08: ffff881026a48000 R09: 0000000000000000
R10: ffff88102d21efb8 R11: 0000000000000000 R12: ffff881026a48000
R13: 51ffe35600000003 R14: 0000000000000000 R15: 0000000000004450
FS: 00007fbd37a2d7e0(0000) GS:ffff88103fca0000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fbd37a47000 CR3: 000000103dc78000 CR4: 00000000000407e0
Stack:
ffff881026a4c450 0000000000005227 ffffffff81a3703d ffff881026a48000
2e2edd7000000000 ffff88103db34140 000000000001abaf 3638303900000000
0000003a00000fb8 ffff881026a48000 ffff88102d21e000 000000000000448a
Call Trace:
[<ffffffff8126dd7d>] pstore_get_records+0xed/0x2c0
[<ffffffff8126cfa0>] ? pstore_get_inode+0x50/0x50
[<ffffffff8126d042>] pstore_fill_super+0xa2/0xc0
[<ffffffff811691f2>] mount_single+0xa2/0xd0
[<ffffffff8126ce28>] pstore_mount+0x18/0x20
[<ffffffff811693e3>] mount_fs+0x43/0x1b0
[<ffffffff8112dc40>] ? __alloc_percpu+0x10/0x20
[<ffffffff8118256f>] vfs_kern_mount+0x6f/0x100
[<ffffffff81184a79>] do_mount+0x259/0xa10
[<ffffffff81128bcb>] ? strndup_user+0x5b/0x80
[<ffffffff811852be>] SyS_mount+0x8e/0xe0
[<ffffffff81606802>] system_call_fastpath+0x16/0x1b
Code: 88 e8 f1 0f 39 00 48 8b 0d 0a 3a a2 00 48 81 f9 00 0d c9 81 75
15 eb 67 0f 1f 80 00 00 00 00 48 8b 09 48 81 f9 00 0d c9 81 74 54 <44>
39 71 18 75 ee 4c 39 69 20 75 e8 48 39 59 10 75 e2 48 89 c6
RIP [<ffffffff8126d314>] pstore_mkfile+0x84/0x410
RSP <ffff88082e2edc70>
---[ end trace 0e1dd8e3ccfa3dcc ]---
/etc/init.d/functions: line 530: 10252 Segmentation fault "$@"
Here's the start of my pstore_mkfile() code where the GP fault occurred:
ffffffff8126d290 <pstore_mkfile>:
ffffffff8126d290: e8 2b 91 39 00 callq
ffffffff816063c0 <__fentry__>
ffffffff8126d295: 55 push %rbp
ffffffff8126d296: 48 89 e5 mov %rsp,%rbp
ffffffff8126d299: 41 57 push %r15
ffffffff8126d29b: 41 56 push %r14
ffffffff8126d29d: 41 89 fe mov %edi,%r14d
ffffffff8126d2a0: 48 c7 c7 e8 a7 0a 82 mov $0xffffffff820aa7e8,%rdi
ffffffff8126d2a7: 41 55 push %r13
ffffffff8126d2a9: 49 89 d5 mov %rdx,%r13
ffffffff8126d2ac: 41 54 push %r12
ffffffff8126d2ae: 53 push %rbx
ffffffff8126d2af: 48 83 ec 78 sub $0x78,%rsp
ffffffff8126d2b3: 89 4d 84 mov %ecx,-0x7c(%rbp)
ffffffff8126d2b6: 48 89 b5 70 ff ff ff mov %rsi,-0x90(%rbp)
ffffffff8126d2bd: 65 48 8b 04 25 28 00 mov %gs:0x28,%rax
ffffffff8126d2c4: 00 00
ffffffff8126d2c6: 48 89 45 d0 mov %rax,-0x30(%rbp)
ffffffff8126d2ca: 31 c0 xor %eax,%eax
ffffffff8126d2cc: 48 8b 05 0d d5 e3 00 mov
0xe3d50d(%rip),%rax # ffffffff820aa7e0 <pstore_sb>
ffffffff8126d2d3: 4c 89 85 78 ff ff ff mov %r8,-0x88(%rbp)
ffffffff8126d2da: 44 89 4d 80 mov %r9d,-0x80(%rbp)
ffffffff8126d2de: 48 8b 5d 28 mov 0x28(%rbp),%rbx
ffffffff8126d2e2: 48 8b 40 60 mov 0x60(%rax),%rax
ffffffff8126d2e6: 48 89 45 88 mov %rax,-0x78(%rbp)
ffffffff8126d2ea: e8 f1 0f 39 00 callq
ffffffff815fe2e0 <_raw_spin_lock_irqsave>
ffffffff8126d2ef: 48 8b 0d 0a 3a a2 00 mov
0xa23a0a(%rip),%rcx # ffffffff81c90d00 <allpstore>
ffffffff8126d2f6: 48 81 f9 00 0d c9 81 cmp $0xffffffff81c90d00,%rcx
ffffffff8126d2fd: 75 15 jne
ffffffff8126d314 <pstore_mkfile+0x84>
ffffffff8126d2ff: eb 67 jmp
ffffffff8126d368 <pstore_mkfile+0xd8>
ffffffff8126d301: 0f 1f 80 00 00 00 00 nopl 0x0(%rax)
ffffffff8126d308: 48 8b 09 mov (%rcx),%rcx
ffffffff8126d30b: 48 81 f9 00 0d c9 81 cmp $0xffffffff81c90d00,%rcx
ffffffff8126d312: 74 54 je
ffffffff8126d368 <pstore_mkfile+0xd8>
ffffffff8126d314: 44 39 71 18 cmp
%r14d,0x18(%rcx) <<<<<<<<<< GP fault here
ffffffff8126d318: 75 ee jne
ffffffff8126d308 <pstore_mkfile+0x78>
ffffffff8126d31a: 4c 39 69 20 cmp %r13,0x20(%rcx)
ffffffff8126d31e: 75 e8 jne
ffffffff8126d308 <pstore_mkfile+0x78>
ffffffff8126d320: 48 39 59 10 cmp %rbx,0x10(%rcx)
ffffffff8126d324: 75 e2 jne
ffffffff8126d308 <pstore_mkfile+0x78>
ffffffff8126d326: 48 89 c6 mov %rax,%rsi
ffffffff8126d329: 48 c7 c7 e8 a7 0a 82 mov $0xffffffff820aa7e8,%rdi
ffffffff8126d330: e8 1b 0d 39 00 callq
ffffffff815fe050 <_raw_spin_unlock_irqrestore>
Booting a vanilla v3.11-rc4 kernel I can see the files pstore - but
they still seem to have
corruption/missing data at the end when I decode with openssl zlib -d :-(
So start by peering at the path that I applied to make sure I didn't mess up.
Strangely I am not ablereproduce this on power or on system-x. With system-x I was
able to loga single record and decompression did not give me any junk characters
at the
end. Not sure if its the header which is missing.If it was I should have encountered
same issue on Power too. Please give a final try with the patch I have attached
and I
will dig into this more tomorrow. Patch to be applied on top of my patch series
(without your fix patch).
- Aruna
From: Tony Luck <hidden> Date: 2013-08-05 21:20:46
This patch seems to fix the garbage at the end problem. Booting an
old kernel and using openssl decodes them OK.
Still have problems booting if there are any compressed images in ERST
to be inflated.
-Tony
From: Tony Luck <hidden> Date: 2013-08-06 23:36:15
On Mon, Aug 5, 2013 at 2:20 PM, Tony Luck [off-list ref] wrote:
Still have problems booting if there are any compressed images in ERST
to be inflated.
So I took another look at this part of the code ... and saw a couple of issues:
while ((size = psi->read(&id, &type, &count, &time, &buf, &compressed,
psi)) > 0) {
if (compressed && (type == PSTORE_TYPE_DMESG)) {
big_buf_sz = (psinfo->bufsize * 100) / 45;
big_buf = allocate_buf_for_decompression(big_buf_sz);
if (big_buf || stream.workspace)
Need an "else" here to set unzipped_len to -1 (or set it to -1 down
at the bottom of the loop ready for next time around.
if (unzipped_len > 0) {
buf = big_buf;
quoted
quoted
This sets us up for problems. First, you just overwrote the address
of the buffer that psi->read allocated - so we have a memory leak. But
worse than that we now double free the same buffer below when we
kfree(buf) and then kfree(big_buf)
size = unzipped_len;
compressed = false;
} else {
pr_err("pstore: decompression failed;"
"returned %d\n", unzipped_len);
compressed = true;
}
}
rc = pstore_mkfile(type, psi->name, id, count, buf,
compressed, (size_t)size, time, psi);
kfree(buf);
kfree(stream.workspace);
kfree(big_buf);
buf = NULL;
stream.workspace = NULL;
big_buf = NULL;
if (rc && (rc != -EEXIST || !quiet))
failed++;
}
See attached patch that fixes these - but the code still looks like it
could be cleaned up a bit more.
-Tony
On Wednesday 07 August 2013 05:06 AM, Tony Luck wrote:
On Mon, Aug 5, 2013 at 2:20 PM, Tony Luck [off-list ref] wrote:
quoted
Still have problems booting if there are any compressed images in ERST
to be inflated.
So I took another look at this part of the code ... and saw a couple of issues:
while ((size = psi->read(&id, &type, &count, &time, &buf, &compressed,
psi)) > 0) {
if (compressed && (type == PSTORE_TYPE_DMESG)) {
big_buf_sz = (psinfo->bufsize * 100) / 45;
big_buf = allocate_buf_for_decompression(big_buf_sz);
if (big_buf || stream.workspace)
Need an "else" here to set unzipped_len to -1 (or set it to -1 down
at the bottom of the loop ready for next time around.
if (unzipped_len > 0) {
buf = big_buf;
quoted
quoted
quoted
This sets us up for problems. First, you just overwrote the address
of the buffer that psi->read allocated - so we have a memory leak. But
worse than that we now double free the same buffer below when we
kfree(buf) and then kfree(big_buf)
size = unzipped_len;
compressed = false;
} else {
pr_err("pstore: decompression failed;"
"returned %d\n", unzipped_len);
compressed = true;
}
}
rc = pstore_mkfile(type, psi->name, id, count, buf,
compressed, (size_t)size, time, psi);
kfree(buf);
kfree(stream.workspace);
kfree(big_buf);
buf = NULL;
stream.workspace = NULL;
big_buf = NULL;
if (rc && (rc != -EEXIST || !quiet))
failed++;
}
See attached patch that fixes these - but the code still looks like it
could be cleaned up a bit more.
The patch looks right. I will clean it up. Does the issue still persist after this?
Where does the magic multiply by 1.45 come from? Is that always enough
for the decompression of "dmesg" type data to succeed?
I had this in my cover letter of the series, posting the same from it
Writing to persistent store
----------------------------
Compression will reduce the size of oops/panic report to atmost 45% of its
original size. (Based on experiments done while providing compression support
to nvram by Jim keniston).
Hence buffer of size ( (100/45 approx 2.22) *<registered_buffer> is allocated).
The compression parameters selected based on some experiments:
compression_level = 6, window_bits = 12, memory_level = 4 which achieved a
significant compression of 12 % of uncompressed buffer size tried upto 36k.
Data is compressed from the bigger buffer to registered buffer which is
returned to backends.
Pstore will indicate that with a flag 'compressed' which is passed to backends.
Using this flag, backends will add a flag in their header to indicate the data
is compressed or not while writing to persistent store.
The significant compression that I have mentioned had repeated occurrences in the
text. When I tried with plain text I saw compression of around 45% with compression
parameters I have used.
If the record size is fixed across all the backends then it would be easy to come
up with a pre defined set of compression parameters as well as the buffer size of
compressed/decompressed data based on experiments. In power as of now, the maximum size
of the record is 4k. So compression support on power was provided with multiply (100/45)
considering the maximum record size to be 4k.
How is it with erst and efivars?
- Aruna
From: Tony Luck <hidden> Date: 2013-08-07 05:35:21
On Tue, Aug 6, 2013 at 10:13 PM, Aruna Balakrishnaiah
[off-list ref] wrote:
How is it with erst and efivars?
ERST is at the whim of the BIOS writer (the ACPI standard doesn't provide any
suggestions on record sizes). My systems support ~6K record size.
efivars has, IIRC, a 1k limit coded in the Linux back end.
-Tony
From: Tony Luck <hidden> Date: 2013-08-07 17:30:12
Oh - one more thing - and my apologies for not spotting this before:
dst = allocate_buf_for_compression(big_buf_sz);
No - you may not call kmalloc() in oops/panic context. Please pre-allocate
everything you need in some initialization code to make sure that we don't
fail in the panic path because we can't get the memory we need.
-Tony
From: Tony Luck <hidden> Date: 2013-08-07 22:22:49
On Tue, Aug 6, 2013 at 10:35 PM, Tony Luck [off-list ref] wrote:
ERST is at the whim of the BIOS writer (the ACPI standard doesn't provide any
suggestions on record sizes). My systems support ~6K record size.
Off by a little - 7896 bytes on my current machine.
efivars has, IIRC, a 1k limit coded in the Linux back end.
My memory was correct for this one.
Adding a little tracing to pstore_getrecords() I see this:
pstore: inflated 3880 bytes compressed to 17459 bytes
pstore: inflated 2567 bytes compressed to 17531 bytes
pstore: inflated 4018 bytes compressed to 17488 bytes
Which isn't at all what I expected. The ERST backend
advertised a bufsize of 7896, and I have the default
kmsg_bytes of 10240. So on my forced panic the code
decided to create a three part pstore dump. The sum of
the pieces is close to, but a little over the target of 10K.
But I don't understand why the compressed sizes are so
much smaller that the ERST backend block size.
The uncompressed sizes appear to be close to constant.
The compression ratios vary from 14% to 23%
Why do we get three small parts instead of two bigger
ones close the the 7896 ERST bufsize?
-Tony
Hi Tony,
On Thursday 08 August 2013 03:52 AM, Tony Luck wrote:
On Tue, Aug 6, 2013 at 10:35 PM, Tony Luck [off-list ref] wrote:
quoted
ERST is at the whim of the BIOS writer (the ACPI standard doesn't provide any
suggestions on record sizes). My systems support ~6K record size.
Off by a little - 7896 bytes on my current machine.
quoted
efivars has, IIRC, a 1k limit coded in the Linux back end.
My memory was correct for this one.
Adding a little tracing to pstore_getrecords() I see this:
pstore: inflated 3880 bytes compressed to 17459 bytes
pstore: inflated 2567 bytes compressed to 17531 bytes
pstore: inflated 4018 bytes compressed to 17488 bytes
Which isn't at all what I expected. The ERST backend
advertised a bufsize of 7896, and I have the default
kmsg_bytes of 10240. So on my forced panic the code
decided to create a three part pstore dump. The sum of
the pieces is close to, but a little over the target of 10K.
But I don't understand why the compressed sizes are so
much smaller that the ERST backend block size.
The sizes of compressed text depends on the nature of uncompressed
data that is captured from kmsg_dump, considering the worst
case of plain text based on experiments 45% was thecompression achieved.
So we chose a buffer of size psinfo->bufsize * 100/45.
If the uncompressed data captured was more of plain text nature then it
would take up size close to ERST backend block size. Thats the reason
you see compressed data of 2.5k to 4.0k. 2.5k would have more
repeated occurrences than 4.0k.
The sum of 3 pstore records should not have exceeded kmsg_bytes.
Is it after adding total_len in the fix patch? Will take a look at it.
The uncompressed sizes appear to be close to constant.
The compression ratios vary from 14% to 23%
Why do we get three small parts instead of two bigger
ones close the the 7896 ERST bufsize?
On Wednesday 07 August 2013 11:00 PM, Tony Luck wrote:
Oh - one more thing - and my apologies for not spotting this before:
dst = allocate_buf_for_compression(big_buf_sz);
No - you may not call kmalloc() in oops/panic context. Please pre-allocate
everything you need in some initialization code to make sure that we don't
fail in the panic path because we can't get the memory we need.
-Tony
Sure. I had this in mind. At the same time memory consumed for compression is
quite high.
For the compression parameters used, workspace will be 30k and big_buf will be 17.5k
for the record size of 7896 that you have mentioned.
So total memory consumed for compression and decompression will close 47.5k.
When we preallocate, we can use the same big_buf for compression as well as
decompression.
Also workspace will be one for both. By allocating max of inflate workspace size
and deflate
workspace size. We can save memory here.
If pre-allocating close to 50k of buffer is not a issue. We can go ahead with
this approach.
From: Tony Luck <hidden> Date: 2013-08-08 05:05:45
On Wed, Aug 7, 2013 at 9:29 PM, Aruna Balakrishnaiah
[off-list ref] wrote:
When we preallocate, we can use the same big_buf for compression as well as
decompression.
Also workspace will be one for both. By allocating max of inflate workspace
size and deflate
workspace size. We can save memory here.
Well decompression isn't a problem. We are doing that in the non-panicing
context of the freshly booted kernel so we can allocate memory without any
worries for this. It's only the compression during panic where we must
pre-allocate. But if the sizes are close to the same, then we might as well
use the same buffers for both (and simplify the code because we don't have
to worry about the kmalloc/kfree bits.
If pre-allocating close to 50k of buffer is not a issue. We can go ahead
with this approach.
I never care about allocations measured in *kilo*bytes[1] - the smallest systems
I use have 32GB - so 50K is so far down in the noise of other allocations.
But other types of systems might be more concerned. ERST is generally
only implemented on servers ... so the better question might be:
What are the sizes for the EFI backend (where the buffer size is 1024). It
sounds like it should scale linearly ... so below 8K??? That should not
scare many people. Even phones measure memory in hundreds of MBytes.
-Tony
[1] unless they are per-cpu or per something else that there are a lot of
on a big server - but this is a one-per-system allocation.
On Thursday 08 August 2013 09:38 AM, Aruna Balakrishnaiah wrote:
Hi Tony,
On Thursday 08 August 2013 03:52 AM, Tony Luck wrote:
quoted
On Tue, Aug 6, 2013 at 10:35 PM, Tony Luck [off-list ref] wrote:
quoted
ERST is at the whim of the BIOS writer (the ACPI standard doesn't provide any
suggestions on record sizes). My systems support ~6K record size.
Off by a little - 7896 bytes on my current machine.
quoted
efivars has, IIRC, a 1k limit coded in the Linux back end.
My memory was correct for this one.
Adding a little tracing to pstore_getrecords() I see this:
pstore: inflated 3880 bytes compressed to 17459 bytes
pstore: inflated 2567 bytes compressed to 17531 bytes
pstore: inflated 4018 bytes compressed to 17488 bytes
Which isn't at all what I expected. The ERST backend
advertised a bufsize of 7896, and I have the default
kmsg_bytes of 10240. So on my forced panic the code
decided to create a three part pstore dump. The sum of
the pieces is close to, but a little over the target of 10K.
But I don't understand why the compressed sizes are so
much smaller that the ERST backend block size.
The sizes of compressed text depends on the nature of uncompressed
data that is captured from kmsg_dump, considering the worst
case of plain text based on experiments 45% was thecompression achieved.
So we chose a buffer of size psinfo->bufsize * 100/45.
If the uncompressed data captured was more of plain text nature then it
would take up size close to ERST backend block size. Thats the reason
you see compressed data of 2.5k to 4.0k. 2.5k would have more
repeated occurrences than 4.0k.
The sum of 3 pstore records should not have exceeded kmsg_bytes.
Is it after adding total_len in the fix patch? Will take a look at it.
The sum of first two records is less than kmsg_bytes, so it captures the 3rd record.
Only after 3rd record is captured and written total is evaluated against kmsg_bytes
when itexceeds the limit it stops capturing the next one.
This shall happen even without compression right? If total is checked before
write this can be avoided.
- Aruna
quoted
The uncompressed sizes appear to be close to constant.
The compression ratios vary from 14% to 23%
Why do we get three small parts instead of two bigger
ones close the the 7896 ERST bufsize?