Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Mathieu Desnoyers]

Hi Martin,

Can you reformat your patch with diff -urN so I can apply it with patch ?

Thanks!

Mathieu

----- On Jun 8, 2015, at 11:19 AM, Martin Leisener martin@leisener.de wrote:

> Hi Mathieu,
> 
> thanks for merging my arm patch! I found one more issue during my lttng-modules
> usages,
> which can happen in low/fragmented memory situations. Please have a look, if you
> find this
> patch useful/mergable. Again it is tested on x86 Ubuntu 12.04 LTS as well as my
> imx6 arm board.
> 
> Regards Martin
> 
> 
> On a small arm imx6 solo with 256MB RAM it often happens that memory becomes
> fragmented rather
> quickly, so that kmalloc will not be able to get enough consecutive pages
> (enocuntered for
> example if you enable all kernel events: lttng enable-event -k syscall --all).
> 
> This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu 12.04
> Lts
> and on imx6 solo 256MB RAM
> 
> If this patch is not applied, you can identify low and/or fragmented memory
> failures by
> looking at the kernel ring buffer (please ignore DMA, it is due to some memory
> setup
> misconfiguration, should read Normal):
> 
> ...
> [  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
> ...
> [  321.994711] lowmem_reserve[]: 0 0 0
> [  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC)
> 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB
> 0*16384kB 0*32768kB = 46068kB
> 
> Signed-off-by: Martin Leisener <martin@leisener.de>
> ---
> lttng-events.c |   16 +++++++++++-----
> 1 file changed, 11 insertions(+), 5 deletions(-)
> 
> diff --git a/lttng-events.c b/lttng-events.c
> index 7eec04c..c861f71 100644
> --- a/lttng-events.c
> +++ b/lttng-events.c
> @@ -39,6 +39,7 @@
> #include "wrapper/file.h"
> #include <linux/jhash.h>
> #include <linux/uaccess.h>
> +#include <linux/vmalloc.h>
>  #include "wrapper/uuid.h"
> #include "wrapper/vmalloc.h"	/* for wrapper_vmalloc_sync_all() */
> @@ -132,10 +133,10 @@ struct lttng_session *lttng_session_create(void)
> 			GFP_KERNEL);
> 	if (!metadata_cache)
> 		goto err_free_session;
> -	metadata_cache->data = kzalloc(METADATA_CACHE_DEFAULT_SIZE,
> -			GFP_KERNEL);
> +	metadata_cache->data = vmalloc(METADATA_CACHE_DEFAULT_SIZE);
> 	if (!metadata_cache->data)
> 		goto err_free_cache;
> +	memset(metadata_cache->data, 0, METADATA_CACHE_DEFAULT_SIZE);
> 	metadata_cache->cache_alloc = METADATA_CACHE_DEFAULT_SIZE;
> 	kref_init(&metadata_cache->refcount);
> 	session->metadata_cache = metadata_cache;
> @@ -162,7 +163,7 @@ void metadata_cache_destroy(struct kref *kref)
> {
> 	struct lttng_metadata_cache *cache =
> 		container_of(kref, struct lttng_metadata_cache, refcount);
> -	kfree(cache->data);
> +	vfree(cache->data);
> 	kfree(cache);
> }
> @@ -1523,10 +1524,15 @@ int lttng_metadata_printf(struct lttng_session *session,
> 		tmp_cache_alloc_size = max_t(unsigned int,
> 				session->metadata_cache->cache_alloc + len,
> 				session->metadata_cache->cache_alloc << 1);
> -		tmp_cache_realloc = krealloc(session->metadata_cache->data,
> -				tmp_cache_alloc_size, GFP_KERNEL);
> +		tmp_cache_realloc = vmalloc(tmp_cache_alloc_size);
> 		if (!tmp_cache_realloc)
> 			goto err;
> +		else if (session->metadata_cache->data) {
> +			memset(tmp_cache_realloc, 0, tmp_cache_alloc_size);
> +			memcpy(tmp_cache_realloc, session->metadata_cache->data,
> session->metadata_cache->cache_alloc);
> +			vfree(session->metadata_cache->data);
> +		}
> +
> 		session->metadata_cache->cache_alloc = tmp_cache_alloc_size;
> 		session->metadata_cache->data = tmp_cache_realloc;
> 	}
> --
> 1.7.9.5
> 
> 
> _______________________________________________
> lttng-dev mailing list
> lttng-dev@lists.lttng.org
> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Martin Leisener]

Hi Mathieu,

sorry for sending the broken patch, I fell for some "smart" formating of my email client, I cannot utilize it myself the way I send it.
Hence I now send the patch again as it was original intended. Sent to myself, I can apply it, so I hope it now works in general as well
I examined as recommended diff -urN, it seems the output can be utilized by patch the same way as git diff.
Hope it is now received the way I intended.

Regards Martin	



On a small arm imx6 solo with 256MB RAM it often happens that memory becomes fragmented rather
quickly, so that kmalloc will not be able to get enough consecutive pages (enocuntered for
example if you enable all kernel events: lttng enable-event -k syscall --all).

This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu 12.04 Lts
and on imx6 solo 256MB RAM

If this patch is not applied, you can identify low and/or fragmented memory failures by
looking at the kernel ring buffer (please ignore DMA, it is due to some memory setup
misconfiguration, should read Normal):

...
[  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
...
[  321.994711] lowmem_reserve[]: 0 0 0
[  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC) 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB 0*16384kB 0*32768kB = 46068kB

Signed-off-by: Martin Leisener <martin@leisener.de>

diff -urN a/lttng-events.c lttng-modules/lttng-events.c
--- a/lttng-events.c	2015-06-10 14:36:51.143083012 +0200
+++ lttng-modules/lttng-events.c	2015-06-10 14:48:05.846662088 +0200
@@ -39,6 +39,7 @@
 #include "wrapper/file.h"
 #include <linux/jhash.h>
 #include <linux/uaccess.h>
+#include <linux/vmalloc.h>

 #include "wrapper/uuid.h"
 #include "wrapper/vmalloc.h"	/* for wrapper_vmalloc_sync_all() */
@@ -132,10 +133,10 @@
 			GFP_KERNEL);
 	if (!metadata_cache)
 		goto err_free_session;
-	metadata_cache->data = kzalloc(METADATA_CACHE_DEFAULT_SIZE,
-			GFP_KERNEL);
+	metadata_cache->data = vmalloc(METADATA_CACHE_DEFAULT_SIZE);
 	if (!metadata_cache->data)
 		goto err_free_cache;
+	memset(metadata_cache->data, 0, METADATA_CACHE_DEFAULT_SIZE);
 	metadata_cache->cache_alloc = METADATA_CACHE_DEFAULT_SIZE;
 	kref_init(&metadata_cache->refcount);
 	session->metadata_cache = metadata_cache;
@@ -162,7 +163,7 @@
 {
 	struct lttng_metadata_cache *cache =
 		container_of(kref, struct lttng_metadata_cache, refcount);
-	kfree(cache->data);
+	vfree(cache->data);
 	kfree(cache);
 }

@@ -1523,10 +1524,15 @@
 		tmp_cache_alloc_size = max_t(unsigned int,
 				session->metadata_cache->cache_alloc + len,
 				session->metadata_cache->cache_alloc << 1);
-		tmp_cache_realloc = krealloc(session->metadata_cache->data,
-				tmp_cache_alloc_size, GFP_KERNEL);
+		tmp_cache_realloc = vmalloc(tmp_cache_alloc_size);
 		if (!tmp_cache_realloc)
 			goto err;
+		else if (session->metadata_cache->data) {
+			memset(tmp_cache_realloc, 0, tmp_cache_alloc_size);
+			memcpy(tmp_cache_realloc, session->metadata_cache->data, session->metadata_cache->cache_alloc);
+			vfree(session->metadata_cache->data);
+		}
+
 		session->metadata_cache->cache_alloc = tmp_cache_alloc_size;
 		session->metadata_cache->data = tmp_cache_realloc;
 	}




On 06/10/2015 09:14 AM, Mathieu Desnoyers wrote:
> Hi Martin,
> 
> Can you reformat your patch with diff -urN so I can apply it with patch ?
> 
> Thanks!
> 
> Mathieu
> 
> ----- On Jun 8, 2015, at 11:19 AM, Martin Leisener martin@leisener.de wrote:
> 
>> Hi Mathieu,
>>
>> thanks for merging my arm patch! I found one more issue during my lttng-modules
>> usages,
>> which can happen in low/fragmented memory situations. Please have a look, if you
>> find this
>> patch useful/mergable. Again it is tested on x86 Ubuntu 12.04 LTS as well as my
>> imx6 arm board.
>>
>> Regards Martin
>>
>>
>> On a small arm imx6 solo with 256MB RAM it often happens that memory becomes
>> fragmented rather
>> quickly, so that kmalloc will not be able to get enough consecutive pages
>> (enocuntered for
>> example if you enable all kernel events: lttng enable-event -k syscall --all).
>>
>> This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu 12.04
>> Lts
>> and on imx6 solo 256MB RAM
>>
>> If this patch is not applied, you can identify low and/or fragmented memory
>> failures by
>> looking at the kernel ring buffer (please ignore DMA, it is due to some memory
>> setup
>> misconfiguration, should read Normal):
>>
>> ...
>> [  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
>> ...
>> [  321.994711] lowmem_reserve[]: 0 0 0
>> [  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC)
>> 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB
>> 0*16384kB 0*32768kB = 46068kB
>>
>> Signed-off-by: Martin Leisener <martin@leisener.de>
>> ---
>> lttng-events.c |   16 +++++++++++-----
>> 1 file changed, 11 insertions(+), 5 deletions(-)
>>
>> diff --git a/lttng-events.c b/lttng-events.c
>> index 7eec04c..c861f71 100644
>> --- a/lttng-events.c
>> +++ b/lttng-events.c
>> @@ -39,6 +39,7 @@
>> #include "wrapper/file.h"
>> #include <linux/jhash.h>
>> #include <linux/uaccess.h>
>> +#include <linux/vmalloc.h>
>>  #include "wrapper/uuid.h"
>> #include "wrapper/vmalloc.h"	/* for wrapper_vmalloc_sync_all() */
>> @@ -132,10 +133,10 @@ struct lttng_session *lttng_session_create(void)
>> 			GFP_KERNEL);
>> 	if (!metadata_cache)
>> 		goto err_free_session;
>> -	metadata_cache->data = kzalloc(METADATA_CACHE_DEFAULT_SIZE,
>> -			GFP_KERNEL);
>> +	metadata_cache->data = vmalloc(METADATA_CACHE_DEFAULT_SIZE);
>> 	if (!metadata_cache->data)
>> 		goto err_free_cache;
>> +	memset(metadata_cache->data, 0, METADATA_CACHE_DEFAULT_SIZE);
>> 	metadata_cache->cache_alloc = METADATA_CACHE_DEFAULT_SIZE;
>> 	kref_init(&metadata_cache->refcount);
>> 	session->metadata_cache = metadata_cache;
>> @@ -162,7 +163,7 @@ void metadata_cache_destroy(struct kref *kref)
>> {
>> 	struct lttng_metadata_cache *cache =
>> 		container_of(kref, struct lttng_metadata_cache, refcount);
>> -	kfree(cache->data);
>> +	vfree(cache->data);
>> 	kfree(cache);
>> }
>> @@ -1523,10 +1524,15 @@ int lttng_metadata_printf(struct lttng_session *session,
>> 		tmp_cache_alloc_size = max_t(unsigned int,
>> 				session->metadata_cache->cache_alloc + len,
>> 				session->metadata_cache->cache_alloc << 1);
>> -		tmp_cache_realloc = krealloc(session->metadata_cache->data,
>> -				tmp_cache_alloc_size, GFP_KERNEL);
>> +		tmp_cache_realloc = vmalloc(tmp_cache_alloc_size);
>> 		if (!tmp_cache_realloc)
>> 			goto err;
>> +		else if (session->metadata_cache->data) {
>> +			memset(tmp_cache_realloc, 0, tmp_cache_alloc_size);
>> +			memcpy(tmp_cache_realloc, session->metadata_cache->data,
>> session->metadata_cache->cache_alloc);
>> +			vfree(session->metadata_cache->data);
>> +		}
>> +
>> 		session->metadata_cache->cache_alloc = tmp_cache_alloc_size;
>> 		session->metadata_cache->data = tmp_cache_realloc;
>> 	}
>> --
>> 1.7.9.5
>>
>>
>> _______________________________________________
>> lttng-dev mailing list
>> lttng-dev@lists.lttng.org
>> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
> 

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Mathieu Desnoyers]

----- On Jun 10, 2015, at 9:17 AM, Martin Leisener martin@leisener.de wrote:

> Hi Mathieu,
> 
> sorry for sending the broken patch, I fell for some "smart" formating of my
> email client, I cannot utilize it myself the way I send it.
> Hence I now send the patch again as it was original intended. Sent to myself, I
> can apply it, so I hope it now works in general as well
> I examined as recommended diff -urN, it seems the output can be utilized by
> patch the same way as git diff.
> Hope it is now received the way I intended.

Hi Martin,

I tried you patch on a x86-64 machine (my laptop), and although taking a
single kernel trace worked fine, it appears to OOPS when I run

(in lttng-tools)
cd tests
./run.sh root_regression

Not sure if it's a race within lttng-modules that gets triggered by using
virtual mem rather than linear mapping, or if it's something else...

Thoughts ?

Thanks,

Mathieu

> 
> Regards Martin
> 
> 
> 
> On a small arm imx6 solo with 256MB RAM it often happens that memory becomes
> fragmented rather
> quickly, so that kmalloc will not be able to get enough consecutive pages
> (enocuntered for
> example if you enable all kernel events: lttng enable-event -k syscall --all).
> 
> This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu 12.04
> Lts
> and on imx6 solo 256MB RAM
> 
> If this patch is not applied, you can identify low and/or fragmented memory
> failures by
> looking at the kernel ring buffer (please ignore DMA, it is due to some memory
> setup
> misconfiguration, should read Normal):
> 
> ...
> [  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
> ...
> [  321.994711] lowmem_reserve[]: 0 0 0
> [  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC)
> 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB
> 0*16384kB 0*32768kB = 46068kB
> 
> Signed-off-by: Martin Leisener <martin@leisener.de>
> 
> diff -urN a/lttng-events.c lttng-modules/lttng-events.c
> --- a/lttng-events.c	2015-06-10 14:36:51.143083012 +0200
> +++ lttng-modules/lttng-events.c	2015-06-10 14:48:05.846662088 +0200
> @@ -39,6 +39,7 @@
> #include "wrapper/file.h"
> #include <linux/jhash.h>
> #include <linux/uaccess.h>
> +#include <linux/vmalloc.h>
> 
> #include "wrapper/uuid.h"
> #include "wrapper/vmalloc.h"	/* for wrapper_vmalloc_sync_all() */
> @@ -132,10 +133,10 @@
> 			GFP_KERNEL);
> 	if (!metadata_cache)
> 		goto err_free_session;
> -	metadata_cache->data = kzalloc(METADATA_CACHE_DEFAULT_SIZE,
> -			GFP_KERNEL);
> +	metadata_cache->data = vmalloc(METADATA_CACHE_DEFAULT_SIZE);
> 	if (!metadata_cache->data)
> 		goto err_free_cache;
> +	memset(metadata_cache->data, 0, METADATA_CACHE_DEFAULT_SIZE);
> 	metadata_cache->cache_alloc = METADATA_CACHE_DEFAULT_SIZE;
> 	kref_init(&metadata_cache->refcount);
> 	session->metadata_cache = metadata_cache;
> @@ -162,7 +163,7 @@
> {
> 	struct lttng_metadata_cache *cache =
> 		container_of(kref, struct lttng_metadata_cache, refcount);
> -	kfree(cache->data);
> +	vfree(cache->data);
> 	kfree(cache);
> }
> 
> @@ -1523,10 +1524,15 @@
> 		tmp_cache_alloc_size = max_t(unsigned int,
> 				session->metadata_cache->cache_alloc + len,
> 				session->metadata_cache->cache_alloc << 1);
> -		tmp_cache_realloc = krealloc(session->metadata_cache->data,
> -				tmp_cache_alloc_size, GFP_KERNEL);
> +		tmp_cache_realloc = vmalloc(tmp_cache_alloc_size);
> 		if (!tmp_cache_realloc)
> 			goto err;
> +		else if (session->metadata_cache->data) {
> +			memset(tmp_cache_realloc, 0, tmp_cache_alloc_size);
> +			memcpy(tmp_cache_realloc, session->metadata_cache->data,
> session->metadata_cache->cache_alloc);
> +			vfree(session->metadata_cache->data);
> +		}
> +
> 		session->metadata_cache->cache_alloc = tmp_cache_alloc_size;
> 		session->metadata_cache->data = tmp_cache_realloc;
> 	}
> 
> 
> 
> 
> On 06/10/2015 09:14 AM, Mathieu Desnoyers wrote:
>> Hi Martin,
>> 
>> Can you reformat your patch with diff -urN so I can apply it with patch ?
>> 
>> Thanks!
>> 
>> Mathieu
>> 
>> ----- On Jun 8, 2015, at 11:19 AM, Martin Leisener martin@leisener.de wrote:
>> 
>>> Hi Mathieu,
>>>
>>> thanks for merging my arm patch! I found one more issue during my lttng-modules
>>> usages,
>>> which can happen in low/fragmented memory situations. Please have a look, if you
>>> find this
>>> patch useful/mergable. Again it is tested on x86 Ubuntu 12.04 LTS as well as my
>>> imx6 arm board.
>>>
>>> Regards Martin
>>>
>>>
>>> On a small arm imx6 solo with 256MB RAM it often happens that memory becomes
>>> fragmented rather
>>> quickly, so that kmalloc will not be able to get enough consecutive pages
>>> (enocuntered for
>>> example if you enable all kernel events: lttng enable-event -k syscall --all).
>>>
>>> This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu 12.04
>>> Lts
>>> and on imx6 solo 256MB RAM
>>>
>>> If this patch is not applied, you can identify low and/or fragmented memory
>>> failures by
>>> looking at the kernel ring buffer (please ignore DMA, it is due to some memory
>>> setup
>>> misconfiguration, should read Normal):
>>>
>>> ...
>>> [  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
>>> ...
>>> [  321.994711] lowmem_reserve[]: 0 0 0
>>> [  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC)
>>> 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB
>>> 0*16384kB 0*32768kB = 46068kB
>>>
>>> Signed-off-by: Martin Leisener <martin@leisener.de>
>>> ---
>>> lttng-events.c |   16 +++++++++++-----
>>> 1 file changed, 11 insertions(+), 5 deletions(-)
>>>
>>> diff --git a/lttng-events.c b/lttng-events.c
>>> index 7eec04c..c861f71 100644
>>> --- a/lttng-events.c
>>> +++ b/lttng-events.c
>>> @@ -39,6 +39,7 @@
>>> #include "wrapper/file.h"
>>> #include <linux/jhash.h>
>>> #include <linux/uaccess.h>
>>> +#include <linux/vmalloc.h>
>>>  #include "wrapper/uuid.h"
>>> #include "wrapper/vmalloc.h"	/* for wrapper_vmalloc_sync_all() */
>>> @@ -132,10 +133,10 @@ struct lttng_session *lttng_session_create(void)
>>> 			GFP_KERNEL);
>>> 	if (!metadata_cache)
>>> 		goto err_free_session;
>>> -	metadata_cache->data = kzalloc(METADATA_CACHE_DEFAULT_SIZE,
>>> -			GFP_KERNEL);
>>> +	metadata_cache->data = vmalloc(METADATA_CACHE_DEFAULT_SIZE);
>>> 	if (!metadata_cache->data)
>>> 		goto err_free_cache;
>>> +	memset(metadata_cache->data, 0, METADATA_CACHE_DEFAULT_SIZE);
>>> 	metadata_cache->cache_alloc = METADATA_CACHE_DEFAULT_SIZE;
>>> 	kref_init(&metadata_cache->refcount);
>>> 	session->metadata_cache = metadata_cache;
>>> @@ -162,7 +163,7 @@ void metadata_cache_destroy(struct kref *kref)
>>> {
>>> 	struct lttng_metadata_cache *cache =
>>> 		container_of(kref, struct lttng_metadata_cache, refcount);
>>> -	kfree(cache->data);
>>> +	vfree(cache->data);
>>> 	kfree(cache);
>>> }
>>> @@ -1523,10 +1524,15 @@ int lttng_metadata_printf(struct lttng_session *session,
>>> 		tmp_cache_alloc_size = max_t(unsigned int,
>>> 				session->metadata_cache->cache_alloc + len,
>>> 				session->metadata_cache->cache_alloc << 1);
>>> -		tmp_cache_realloc = krealloc(session->metadata_cache->data,
>>> -				tmp_cache_alloc_size, GFP_KERNEL);
>>> +		tmp_cache_realloc = vmalloc(tmp_cache_alloc_size);
>>> 		if (!tmp_cache_realloc)
>>> 			goto err;
>>> +		else if (session->metadata_cache->data) {
>>> +			memset(tmp_cache_realloc, 0, tmp_cache_alloc_size);
>>> +			memcpy(tmp_cache_realloc, session->metadata_cache->data,
>>> session->metadata_cache->cache_alloc);
>>> +			vfree(session->metadata_cache->data);
>>> +		}
>>> +
>>> 		session->metadata_cache->cache_alloc = tmp_cache_alloc_size;
>>> 		session->metadata_cache->data = tmp_cache_realloc;
>>> 	}
>>> --
>>> 1.7.9.5
>>>
>>>
>>> _______________________________________________
>>> lttng-dev mailing list
>>> lttng-dev@lists.lttng.org
>>> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Martin Leisener]

On 06/13/2015 09:32 PM, Mathieu Desnoyers wrote:
> ----- On Jun 10, 2015, at 9:17 AM, Martin Leisener martin@leisener.de wrote:
> 
>> Hi Mathieu,
>>
>> sorry for sending the broken patch, I fell for some "smart" formating of my
>> email client, I cannot utilize it myself the way I send it.
>> Hence I now send the patch again as it was original intended. Sent to myself, I
>> can apply it, so I hope it now works in general as well
>> I examined as recommended diff -urN, it seems the output can be utilized by
>> patch the same way as git diff.
>> Hope it is now received the way I intended.
> 
> Hi Martin,
> 
> I tried you patch on a x86-64 machine (my laptop), and although taking a
> single kernel trace worked fine, it appears to OOPS when I run
> 
> (in lttng-tools)
> cd tests
> ./run.sh root_regression
> 
> Not sure if it's a race within lttng-modules that gets triggered by using
> virtual mem rather than linear mapping, or if it's something else...
> 
> Thoughts ?
> 
Hi Mathieu,

thanks for testing my patch. I tried the root regression with patched and unpatched
lttng-modules, and found the following result (x86 Ubuntu 12.04 LTS):

martin@OEKAN42PVB:~/src/lttng-tools/tests$ ./run.sh root_regression
regression/kernel/test_all_events ....................... ok
regression/kernel/test_event_basic ...................... ok
regression/kernel/test_syscall .......................... ok
regression/tools/live/test_kernel ....................... No subtests run
regression/tools/live/test_lttng_kernel ................. ok
regression/tools/streaming/test_high_throughput_limits .. ok
regression/tools/streaming/test_kernel .................. ok
regression/tools/snapshots/test_kernel .................. ok
regression/tools/snapshots/test_kernel_streaming ........ ok
regression/tools/health/test_thread_ok .................. ok

Test Summary Report
-------------------
regression/tools/live/test_kernel                     (Wstat: 0 Tests: 0 Failed: 0)
  Parse errors: No plan found in TAP output
Files=10, Tests=2402, 32 wallclock secs ( 0.16 usr  0.02 sys +  0.23 cusr  0.42 csys =  0.83 CPU)
Result: FAIL

Everything runs the same, but for the test_thread_ok, which executes 1-17 with different speeds
sometimes 1/17 takes longer, sometimes 4/17, but I couldn't make it fail.
Same behaviour with patched and unpatched modules.

It always fails (patched and unpatched) when I execute with sudo:
regression/kernel/test_all_events ....................... Dubious, test returned 6 (wstat 1536, 0x600)
...

Since it is not appearing on my system, but in yours it would point more into the direction
of a race.
If it is a race it would be interesting if it can be also triggered via a long running test,
also with the unpatched version (and the patched version on my system)

I will not be able to look into this for the next 3 weeks, unfortunately,
but I plan to setup some long running tests, once I find time again.

Regard Martin

> Thanks,
> 
> Mathieu
> 
>>
>> Regards Martin
>>
>>
>>
>> On a small arm imx6 solo with 256MB RAM it often happens that memory becomes
>> fragmented rather
>> quickly, so that kmalloc will not be able to get enough consecutive pages
>> (enocuntered for
>> example if you enable all kernel events: lttng enable-event -k syscall --all).
>>
>> This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu 12.04
>> Lts
>> and on imx6 solo 256MB RAM
>>
>> If this patch is not applied, you can identify low and/or fragmented memory
>> failures by
>> looking at the kernel ring buffer (please ignore DMA, it is due to some memory
>> setup
>> misconfiguration, should read Normal):
>>
>> ...
>> [  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
>> ...
>> [  321.994711] lowmem_reserve[]: 0 0 0
>> [  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC)
>> 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB
>> 0*16384kB 0*32768kB = 46068kB
>>
>> Signed-off-by: Martin Leisener <martin@leisener.de>
>>
>> diff -urN a/lttng-events.c lttng-modules/lttng-events.c
>> --- a/lttng-events.c	2015-06-10 14:36:51.143083012 +0200
>> +++ lttng-modules/lttng-events.c	2015-06-10 14:48:05.846662088 +0200
>> @@ -39,6 +39,7 @@
>> #include "wrapper/file.h"
>> #include <linux/jhash.h>
>> #include <linux/uaccess.h>
>> +#include <linux/vmalloc.h>
>>
>> #include "wrapper/uuid.h"
>> #include "wrapper/vmalloc.h"	/* for wrapper_vmalloc_sync_all() */
>> @@ -132,10 +133,10 @@
>> 			GFP_KERNEL);
>> 	if (!metadata_cache)
>> 		goto err_free_session;
>> -	metadata_cache->data = kzalloc(METADATA_CACHE_DEFAULT_SIZE,
>> -			GFP_KERNEL);
>> +	metadata_cache->data = vmalloc(METADATA_CACHE_DEFAULT_SIZE);
>> 	if (!metadata_cache->data)
>> 		goto err_free_cache;
>> +	memset(metadata_cache->data, 0, METADATA_CACHE_DEFAULT_SIZE);
>> 	metadata_cache->cache_alloc = METADATA_CACHE_DEFAULT_SIZE;
>> 	kref_init(&metadata_cache->refcount);
>> 	session->metadata_cache = metadata_cache;
>> @@ -162,7 +163,7 @@
>> {
>> 	struct lttng_metadata_cache *cache =
>> 		container_of(kref, struct lttng_metadata_cache, refcount);
>> -	kfree(cache->data);
>> +	vfree(cache->data);
>> 	kfree(cache);
>> }
>>
>> @@ -1523,10 +1524,15 @@
>> 		tmp_cache_alloc_size = max_t(unsigned int,
>> 				session->metadata_cache->cache_alloc + len,
>> 				session->metadata_cache->cache_alloc << 1);
>> -		tmp_cache_realloc = krealloc(session->metadata_cache->data,
>> -				tmp_cache_alloc_size, GFP_KERNEL);
>> +		tmp_cache_realloc = vmalloc(tmp_cache_alloc_size);
>> 		if (!tmp_cache_realloc)
>> 			goto err;
>> +		else if (session->metadata_cache->data) {
>> +			memset(tmp_cache_realloc, 0, tmp_cache_alloc_size);
>> +			memcpy(tmp_cache_realloc, session->metadata_cache->data,
>> session->metadata_cache->cache_alloc);
>> +			vfree(session->metadata_cache->data);
>> +		}
>> +
>> 		session->metadata_cache->cache_alloc = tmp_cache_alloc_size;
>> 		session->metadata_cache->data = tmp_cache_realloc;
>> 	}
>>
>>
>>
>>
>> On 06/10/2015 09:14 AM, Mathieu Desnoyers wrote:
>>> Hi Martin,
>>>
>>> Can you reformat your patch with diff -urN so I can apply it with patch ?
>>>
>>> Thanks!
>>>
>>> Mathieu
>>>
>>> ----- On Jun 8, 2015, at 11:19 AM, Martin Leisener martin@leisener.de wrote:
>>>
>>>> Hi Mathieu,
>>>>
>>>> thanks for merging my arm patch! I found one more issue during my lttng-modules
>>>> usages,
>>>> which can happen in low/fragmented memory situations. Please have a look, if you
>>>> find this
>>>> patch useful/mergable. Again it is tested on x86 Ubuntu 12.04 LTS as well as my
>>>> imx6 arm board.
>>>>
>>>> Regards Martin
>>>>
>>>>
>>>> On a small arm imx6 solo with 256MB RAM it often happens that memory becomes
>>>> fragmented rather
>>>> quickly, so that kmalloc will not be able to get enough consecutive pages
>>>> (enocuntered for
>>>> example if you enable all kernel events: lttng enable-event -k syscall --all).
>>>>
>>>> This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu 12.04
>>>> Lts
>>>> and on imx6 solo 256MB RAM
>>>>
>>>> If this patch is not applied, you can identify low and/or fragmented memory
>>>> failures by
>>>> looking at the kernel ring buffer (please ignore DMA, it is due to some memory
>>>> setup
>>>> misconfiguration, should read Normal):
>>>>
>>>> ...
>>>> [  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
>>>> ...
>>>> [  321.994711] lowmem_reserve[]: 0 0 0
>>>> [  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC)
>>>> 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB
>>>> 0*16384kB 0*32768kB = 46068kB
>>>>
>>>> Signed-off-by: Martin Leisener <martin@leisener.de>
>>>> ---
>>>> lttng-events.c |   16 +++++++++++-----
>>>> 1 file changed, 11 insertions(+), 5 deletions(-)
>>>>
>>>> diff --git a/lttng-events.c b/lttng-events.c
>>>> index 7eec04c..c861f71 100644
>>>> --- a/lttng-events.c
>>>> +++ b/lttng-events.c
>>>> @@ -39,6 +39,7 @@
>>>> #include "wrapper/file.h"
>>>> #include <linux/jhash.h>
>>>> #include <linux/uaccess.h>
>>>> +#include <linux/vmalloc.h>
>>>>  #include "wrapper/uuid.h"
>>>> #include "wrapper/vmalloc.h"	/* for wrapper_vmalloc_sync_all() */
>>>> @@ -132,10 +133,10 @@ struct lttng_session *lttng_session_create(void)
>>>> 			GFP_KERNEL);
>>>> 	if (!metadata_cache)
>>>> 		goto err_free_session;
>>>> -	metadata_cache->data = kzalloc(METADATA_CACHE_DEFAULT_SIZE,
>>>> -			GFP_KERNEL);
>>>> +	metadata_cache->data = vmalloc(METADATA_CACHE_DEFAULT_SIZE);
>>>> 	if (!metadata_cache->data)
>>>> 		goto err_free_cache;
>>>> +	memset(metadata_cache->data, 0, METADATA_CACHE_DEFAULT_SIZE);
>>>> 	metadata_cache->cache_alloc = METADATA_CACHE_DEFAULT_SIZE;
>>>> 	kref_init(&metadata_cache->refcount);
>>>> 	session->metadata_cache = metadata_cache;
>>>> @@ -162,7 +163,7 @@ void metadata_cache_destroy(struct kref *kref)
>>>> {
>>>> 	struct lttng_metadata_cache *cache =
>>>> 		container_of(kref, struct lttng_metadata_cache, refcount);
>>>> -	kfree(cache->data);
>>>> +	vfree(cache->data);
>>>> 	kfree(cache);
>>>> }
>>>> @@ -1523,10 +1524,15 @@ int lttng_metadata_printf(struct lttng_session *session,
>>>> 		tmp_cache_alloc_size = max_t(unsigned int,
>>>> 				session->metadata_cache->cache_alloc + len,
>>>> 				session->metadata_cache->cache_alloc << 1);
>>>> -		tmp_cache_realloc = krealloc(session->metadata_cache->data,
>>>> -				tmp_cache_alloc_size, GFP_KERNEL);
>>>> +		tmp_cache_realloc = vmalloc(tmp_cache_alloc_size);
>>>> 		if (!tmp_cache_realloc)
>>>> 			goto err;
>>>> +		else if (session->metadata_cache->data) {
>>>> +			memset(tmp_cache_realloc, 0, tmp_cache_alloc_size);
>>>> +			memcpy(tmp_cache_realloc, session->metadata_cache->data,
>>>> session->metadata_cache->cache_alloc);
>>>> +			vfree(session->metadata_cache->data);
>>>> +		}
>>>> +
>>>> 		session->metadata_cache->cache_alloc = tmp_cache_alloc_size;
>>>> 		session->metadata_cache->data = tmp_cache_realloc;
>>>> 	}
>>>> --
>>>> 1.7.9.5
>>>>
>>>>
>>>> _______________________________________________
>>>> lttng-dev mailing list
>>>> lttng-dev@lists.lttng.org
>>>> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
> 

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Mathieu Desnoyers]

----- On Jun 15, 2015, at 2:27 PM, Martin Leisener martin@leisener.de wrote:

> On 06/13/2015 09:32 PM, Mathieu Desnoyers wrote:
>> ----- On Jun 10, 2015, at 9:17 AM, Martin Leisener martin@leisener.de wrote:
>> 
>>> Hi Mathieu,
>>>
>>> sorry for sending the broken patch, I fell for some "smart" formating of my
>>> email client, I cannot utilize it myself the way I send it.
>>> Hence I now send the patch again as it was original intended. Sent to myself, I
>>> can apply it, so I hope it now works in general as well
>>> I examined as recommended diff -urN, it seems the output can be utilized by
>>> patch the same way as git diff.
>>> Hope it is now received the way I intended.
>> 
>> Hi Martin,
>> 
>> I tried you patch on a x86-64 machine (my laptop), and although taking a
>> single kernel trace worked fine, it appears to OOPS when I run
>> 
>> (in lttng-tools)
>> cd tests
>> ./run.sh root_regression
>> 
>> Not sure if it's a race within lttng-modules that gets triggered by using
>> virtual mem rather than linear mapping, or if it's something else...
>> 
>> Thoughts ?
>> 
> Hi Mathieu,
> 
> thanks for testing my patch. I tried the root regression with patched and
> unpatched
> lttng-modules, and found the following result (x86 Ubuntu 12.04 LTS):
> 
> martin@OEKAN42PVB:~/src/lttng-tools/tests$ ./run.sh root_regression
> regression/kernel/test_all_events ....................... ok
> regression/kernel/test_event_basic ...................... ok
> regression/kernel/test_syscall .......................... ok
> regression/tools/live/test_kernel ....................... No subtests run
> regression/tools/live/test_lttng_kernel ................. ok
> regression/tools/streaming/test_high_throughput_limits .. ok
> regression/tools/streaming/test_kernel .................. ok
> regression/tools/snapshots/test_kernel .................. ok
> regression/tools/snapshots/test_kernel_streaming ........ ok
> regression/tools/health/test_thread_ok .................. ok
> 
> Test Summary Report
> -------------------
> regression/tools/live/test_kernel                     (Wstat: 0 Tests: 0 Failed:
> 0)
>  Parse errors: No plan found in TAP output
> Files=10, Tests=2402, 32 wallclock secs ( 0.16 usr  0.02 sys +  0.23 cusr  0.42
> csys =  0.83 CPU)
> Result: FAIL
> 
> Everything runs the same, but for the test_thread_ok, which executes 1-17 with
> different speeds
> sometimes 1/17 takes longer, sometimes 4/17, but I couldn't make it fail.
> Same behaviour with patched and unpatched modules.
> 
> It always fails (patched and unpatched) when I execute with sudo:
> regression/kernel/test_all_events ....................... Dubious, test returned
> 6 (wstat 1536, 0x600)
> ...
> 
> Since it is not appearing on my system, but in yours it would point more into
> the direction
> of a race.
> If it is a race it would be interesting if it can be also triggered via a long
> running test,
> also with the unpatched version (and the patched version on my system)
> 
> I will not be able to look into this for the next 3 weeks, unfortunately,
> but I plan to setup some long running tests, once I find time again.

OK. FYI, I have had this issue on a
Linux thinkos 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt9-3~deb8u1 (2015-04-24) x86_64 GNU/Linux
kernel.

I had modified your patch very slightly though, so I will double-check
with your original patch to see if I somehow introduced a regression
by using vzalloc rather than vmalloc+memset(0).

Thanks,

Mathieu

> 
> Regard Martin
> 
>> Thanks,
>> 
>> Mathieu
>> 
>>>
>>> Regards Martin
>>>
>>>
>>>
>>> On a small arm imx6 solo with 256MB RAM it often happens that memory becomes
>>> fragmented rather
>>> quickly, so that kmalloc will not be able to get enough consecutive pages
>>> (enocuntered for
>>> example if you enable all kernel events: lttng enable-event -k syscall --all).
>>>
>>> This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu 12.04
>>> Lts
>>> and on imx6 solo 256MB RAM
>>>
>>> If this patch is not applied, you can identify low and/or fragmented memory
>>> failures by
>>> looking at the kernel ring buffer (please ignore DMA, it is due to some memory
>>> setup
>>> misconfiguration, should read Normal):
>>>
>>> ...
>>> [  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
>>> ...
>>> [  321.994711] lowmem_reserve[]: 0 0 0
>>> [  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC)
>>> 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB
>>> 0*16384kB 0*32768kB = 46068kB
>>>
>>> Signed-off-by: Martin Leisener <martin@leisener.de>
>>>
>>> diff -urN a/lttng-events.c lttng-modules/lttng-events.c
>>> --- a/lttng-events.c	2015-06-10 14:36:51.143083012 +0200
>>> +++ lttng-modules/lttng-events.c	2015-06-10 14:48:05.846662088 +0200
>>> @@ -39,6 +39,7 @@
>>> #include "wrapper/file.h"
>>> #include <linux/jhash.h>
>>> #include <linux/uaccess.h>
>>> +#include <linux/vmalloc.h>
>>>
>>> #include "wrapper/uuid.h"
>>> #include "wrapper/vmalloc.h"	/* for wrapper_vmalloc_sync_all() */
>>> @@ -132,10 +133,10 @@
>>> 			GFP_KERNEL);
>>> 	if (!metadata_cache)
>>> 		goto err_free_session;
>>> -	metadata_cache->data = kzalloc(METADATA_CACHE_DEFAULT_SIZE,
>>> -			GFP_KERNEL);
>>> +	metadata_cache->data = vmalloc(METADATA_CACHE_DEFAULT_SIZE);
>>> 	if (!metadata_cache->data)
>>> 		goto err_free_cache;
>>> +	memset(metadata_cache->data, 0, METADATA_CACHE_DEFAULT_SIZE);
>>> 	metadata_cache->cache_alloc = METADATA_CACHE_DEFAULT_SIZE;
>>> 	kref_init(&metadata_cache->refcount);
>>> 	session->metadata_cache = metadata_cache;
>>> @@ -162,7 +163,7 @@
>>> {
>>> 	struct lttng_metadata_cache *cache =
>>> 		container_of(kref, struct lttng_metadata_cache, refcount);
>>> -	kfree(cache->data);
>>> +	vfree(cache->data);
>>> 	kfree(cache);
>>> }
>>>
>>> @@ -1523,10 +1524,15 @@
>>> 		tmp_cache_alloc_size = max_t(unsigned int,
>>> 				session->metadata_cache->cache_alloc + len,
>>> 				session->metadata_cache->cache_alloc << 1);
>>> -		tmp_cache_realloc = krealloc(session->metadata_cache->data,
>>> -				tmp_cache_alloc_size, GFP_KERNEL);
>>> +		tmp_cache_realloc = vmalloc(tmp_cache_alloc_size);
>>> 		if (!tmp_cache_realloc)
>>> 			goto err;
>>> +		else if (session->metadata_cache->data) {
>>> +			memset(tmp_cache_realloc, 0, tmp_cache_alloc_size);
>>> +			memcpy(tmp_cache_realloc, session->metadata_cache->data,
>>> session->metadata_cache->cache_alloc);
>>> +			vfree(session->metadata_cache->data);
>>> +		}
>>> +
>>> 		session->metadata_cache->cache_alloc = tmp_cache_alloc_size;
>>> 		session->metadata_cache->data = tmp_cache_realloc;
>>> 	}
>>>
>>>
>>>
>>>
>>> On 06/10/2015 09:14 AM, Mathieu Desnoyers wrote:
>>>> Hi Martin,
>>>>
>>>> Can you reformat your patch with diff -urN so I can apply it with patch ?
>>>>
>>>> Thanks!
>>>>
>>>> Mathieu
>>>>
>>>> ----- On Jun 8, 2015, at 11:19 AM, Martin Leisener martin@leisener.de wrote:
>>>>
>>>>> Hi Mathieu,
>>>>>
>>>>> thanks for merging my arm patch! I found one more issue during my lttng-modules
>>>>> usages,
>>>>> which can happen in low/fragmented memory situations. Please have a look, if you
>>>>> find this
>>>>> patch useful/mergable. Again it is tested on x86 Ubuntu 12.04 LTS as well as my
>>>>> imx6 arm board.
>>>>>
>>>>> Regards Martin
>>>>>
>>>>>
>>>>> On a small arm imx6 solo with 256MB RAM it often happens that memory becomes
>>>>> fragmented rather
>>>>> quickly, so that kmalloc will not be able to get enough consecutive pages
>>>>> (enocuntered for
>>>>> example if you enable all kernel events: lttng enable-event -k syscall --all).
>>>>>
>>>>> This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu 12.04
>>>>> Lts
>>>>> and on imx6 solo 256MB RAM
>>>>>
>>>>> If this patch is not applied, you can identify low and/or fragmented memory
>>>>> failures by
>>>>> looking at the kernel ring buffer (please ignore DMA, it is due to some memory
>>>>> setup
>>>>> misconfiguration, should read Normal):
>>>>>
>>>>> ...
>>>>> [  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
>>>>> ...
>>>>> [  321.994711] lowmem_reserve[]: 0 0 0
>>>>> [  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC)
>>>>> 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB
>>>>> 0*16384kB 0*32768kB = 46068kB
>>>>>
>>>>> Signed-off-by: Martin Leisener <martin@leisener.de>
>>>>> ---
>>>>> lttng-events.c |   16 +++++++++++-----
>>>>> 1 file changed, 11 insertions(+), 5 deletions(-)
>>>>>
>>>>> diff --git a/lttng-events.c b/lttng-events.c
>>>>> index 7eec04c..c861f71 100644
>>>>> --- a/lttng-events.c
>>>>> +++ b/lttng-events.c
>>>>> @@ -39,6 +39,7 @@
>>>>> #include "wrapper/file.h"
>>>>> #include <linux/jhash.h>
>>>>> #include <linux/uaccess.h>
>>>>> +#include <linux/vmalloc.h>
>>>>>  #include "wrapper/uuid.h"
>>>>> #include "wrapper/vmalloc.h"	/* for wrapper_vmalloc_sync_all() */
>>>>> @@ -132,10 +133,10 @@ struct lttng_session *lttng_session_create(void)
>>>>> 			GFP_KERNEL);
>>>>> 	if (!metadata_cache)
>>>>> 		goto err_free_session;
>>>>> -	metadata_cache->data = kzalloc(METADATA_CACHE_DEFAULT_SIZE,
>>>>> -			GFP_KERNEL);
>>>>> +	metadata_cache->data = vmalloc(METADATA_CACHE_DEFAULT_SIZE);
>>>>> 	if (!metadata_cache->data)
>>>>> 		goto err_free_cache;
>>>>> +	memset(metadata_cache->data, 0, METADATA_CACHE_DEFAULT_SIZE);
>>>>> 	metadata_cache->cache_alloc = METADATA_CACHE_DEFAULT_SIZE;
>>>>> 	kref_init(&metadata_cache->refcount);
>>>>> 	session->metadata_cache = metadata_cache;
>>>>> @@ -162,7 +163,7 @@ void metadata_cache_destroy(struct kref *kref)
>>>>> {
>>>>> 	struct lttng_metadata_cache *cache =
>>>>> 		container_of(kref, struct lttng_metadata_cache, refcount);
>>>>> -	kfree(cache->data);
>>>>> +	vfree(cache->data);
>>>>> 	kfree(cache);
>>>>> }
>>>>> @@ -1523,10 +1524,15 @@ int lttng_metadata_printf(struct lttng_session *session,
>>>>> 		tmp_cache_alloc_size = max_t(unsigned int,
>>>>> 				session->metadata_cache->cache_alloc + len,
>>>>> 				session->metadata_cache->cache_alloc << 1);
>>>>> -		tmp_cache_realloc = krealloc(session->metadata_cache->data,
>>>>> -				tmp_cache_alloc_size, GFP_KERNEL);
>>>>> +		tmp_cache_realloc = vmalloc(tmp_cache_alloc_size);
>>>>> 		if (!tmp_cache_realloc)
>>>>> 			goto err;
>>>>> +		else if (session->metadata_cache->data) {
>>>>> +			memset(tmp_cache_realloc, 0, tmp_cache_alloc_size);
>>>>> +			memcpy(tmp_cache_realloc, session->metadata_cache->data,
>>>>> session->metadata_cache->cache_alloc);
>>>>> +			vfree(session->metadata_cache->data);
>>>>> +		}
>>>>> +
>>>>> 		session->metadata_cache->cache_alloc = tmp_cache_alloc_size;
>>>>> 		session->metadata_cache->data = tmp_cache_realloc;
>>>>> 	}
>>>>> --
>>>>> 1.7.9.5
>>>>>
>>>>>
>>>>> _______________________________________________
>>>>> lttng-dev mailing list
>>>>> lttng-dev@lists.lttng.org
>>>>> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Jan Glauber]

On Sat, Jun 13, 2015 at 07:32:28PM +0000, Mathieu Desnoyers wrote:
> ----- On Jun 10, 2015, at 9:17 AM, Martin Leisener martin@leisener.de wrote:
> 
> > Hi Mathieu,
> > 
> > sorry for sending the broken patch, I fell for some "smart" formating of my
> > email client, I cannot utilize it myself the way I send it.
> > Hence I now send the patch again as it was original intended. Sent to myself, I
> > can apply it, so I hope it now works in general as well
> > I examined as recommended diff -urN, it seems the output can be utilized by
> > patch the same way as git diff.
> > Hope it is now received the way I intended.
> 
> Hi Martin,
> 
> I tried you patch on a x86-64 machine (my laptop), and although taking a
> single kernel trace worked fine, it appears to OOPS when I run
> 
> (in lttng-tools)
> cd tests
> ./run.sh root_regression

Hi Mathieu,

can you please share the oops message so I can have a look?

Thanks,
Jan

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Mathieu Desnoyers]

[-- Attachment #1: Type: text/plain, Size: 4964 bytes --]

----- On Jun 23, 2015, at 9:46 AM, Jan Glauber jan.glauber@gmail.com wrote:

> On Sat, Jun 13, 2015 at 07:32:28PM +0000, Mathieu Desnoyers wrote:
>> ----- On Jun 10, 2015, at 9:17 AM, Martin Leisener martin@leisener.de wrote:
>> 
>> > Hi Mathieu,
>> > 
>> > sorry for sending the broken patch, I fell for some "smart" formating of my
>> > email client, I cannot utilize it myself the way I send it.
>> > Hence I now send the patch again as it was original intended. Sent to myself, I
>> > can apply it, so I hope it now works in general as well
>> > I examined as recommended diff -urN, it seems the output can be utilized by
>> > patch the same way as git diff.
>> > Hope it is now received the way I intended.
>> 
>> Hi Martin,
>> 
>> I tried you patch on a x86-64 machine (my laptop), and although taking a
>> single kernel trace worked fine, it appears to OOPS when I run
>> 
>> (in lttng-tools)
>> cd tests
>> ./run.sh root_regression
> 
> Hi Mathieu,
> 
> can you please share the oops message so I can have a look?

Sure,

Here is the backtrace happening with the attached patch over lttng-modules
commit 8c6e7f13c778701dec2d6549f1e2ca98970907a0. I modified your patch
slightly.

[ 4078.314978] BUG: unable to handle kernel paging request at ffffc900038d995e
[ 4078.315824] IP: [<ffffffff81316f12>] __memcpy+0x12/0x20
[ 4078.315824] PGD 236c92067 PUD 236c93067 PMD bac0c067 PTE 0
[ 4078.315824] Oops: 0000 [#1] SMP 
[ 4078.315824] Modules linked in: lttng_probe_workqueue(O) lttng_probe_vmscan(O) lttng_probe_udp(O) lttng_probe_timer(O) lttng_probe_sunrpc(O) lttng_probe_statedump(O) lttng_probe_sock(O) lttng_probe_skb(O) lttng_probe_signal(O) lttng_probe_scsi(O) lttng_probe_sched(O) lttng_probe_regmap(O) lttng_probe_rcu(O) lttng_probe_random(O) lttng_probe_printk(O) lttng_probe_power(O) lttng_probe_net(O) lttng_probe_napi(O) lttng_probe_module(O) lttng_probe_kmem(O) lttng_probe_jbd2(O) lttng_probe_irq(O) lttng_probe_ext4(O) lttng_probe_compaction(O) lttng_probe_block(O) lttng_types(O) lttng_ring_buffer_metadata_mmap_client(O) lttng_ring_buffer_client_mmap_overwrite(O) lttng_ring_buffer_client_mmap_discard(O) lttng_ring_buffer_metadata_client(O) lttng_ring_buffer_client_overwrite(O) lttng_ring_buffer_client_discard(O) lttng_tracer(O) lttng_statedump(O) lttng_kprobes(O) lttng_lib_ring_buffer(O) lttng_kretprobes(O) virtio_blk virtio_net virtio_pci virtio_ring virtio
[ 4078.315824] CPU: 5 PID: 4258 Comm: lttng-consumerd Tainted: G           O    4.1.0 #7
[ 4078.315824] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[ 4078.315824] task: ffff8802350c3660 ti: ffff8800bae84000 task.ti: ffff8800bae84000
[ 4078.315824] RIP: 0010:[<ffffffff81316f12>]  [<ffffffff81316f12>] __memcpy+0x12/0x20
[ 4078.315824] RSP: 0018:ffff8800bae87da0  EFLAGS: 00010246
[ 4078.315824] RAX: ffff880235439025 RBX: 0000000000000fd8 RCX: 00000000000001fb
[ 4078.315824] RDX: 0000000000000000 RSI: ffffc900038d995e RDI: ffff880235439025
[ 4078.315824] RBP: ffff8800bae87db8 R08: ffff8800bacecc00 R09: 0000000000008000
[ 4078.315824] R10: 0000000000000000 R11: 0000000000000246 R12: ffff8800bae87dc8
[ 4078.315824] R13: ffff88023466e800 R14: 0000000000000fd8 R15: 0000000000000fd8
[ 4078.315824] FS:  00007f5d3b1cc700(0000) GS:ffff8802372a0000(0000) knlGS:0000000000000000
[ 4078.315824] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 4078.315824] CR2: ffffc900038d995e CR3: 00000000bb1ed000 CR4: 00000000000006e0
[ 4078.315824] Stack:
[ 4078.315824]  ffffffffa01ac797 ffff8800bb5bd480 ffff8800bb5bd4d0 ffff8800bae87e48
[ 4078.315824]  ffffffffa0073060 ffff88023466e800 0000000000000000 0000000000000fd8
[ 4078.315824]  ffffffff00000001 ffff8800bacecc00 0000000000000fd8 0000000000008025
[ 4078.315824] Call Trace:
[ 4078.315824]  [<ffffffffa01ac797>] ? lttng_event_write+0x87/0xb0 [lttng_ring_buffer_metadata_client]
[ 4078.315824]  [<ffffffffa0073060>] lttng_metadata_output_channel+0xd0/0x120 [lttng_tracer]
[ 4078.315824]  [<ffffffffa00755f9>] lttng_metadata_ring_buffer_ioctl+0x79/0xd0 [lttng_tracer]
[ 4078.315824]  [<ffffffff8117ba10>] do_vfs_ioctl+0x2e0/0x4e0
[ 4078.315824]  [<ffffffff812b35c7>] ? file_has_perm+0x87/0xa0
[ 4078.315824]  [<ffffffff8117bc91>] SyS_ioctl+0x81/0xa0
[ 4078.315824]  [<ffffffff810115d1>] ? syscall_trace_leave+0xd1/0xe0
[ 4078.315824]  [<ffffffff818bbd37>] tracesys_phase2+0x84/0x89
[ 4078.315824] Code: 5b 5d c3 66 0f 1f 44 00 00 e8 6b fc ff ff eb e1 90 90 90 90 90 90 90 90 90 0f 1f 44 00 00 48 89 f8 48 89 d1 48 c1 e9 03 83 e2 07 <f3> 48 a5 89 d1 f3 a4 c3 66 0f 1f 44 00 00 48 89 f8 48 89 d1 f3 
[ 4078.315824] RIP  [<ffffffff81316f12>] __memcpy+0x12/0x20
[ 4078.315824]  RSP <ffff8800bae87da0>
[ 4078.315824] CR2: ffffc900038d995e
[ 4078.315824] ---[ end trace a05b652829ceda48 ]---
[ 4078.433848] LTTng: block device enumeration is not supported by kernel


-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0001-Fix-Building-the-event-list-fails-on-fragmented-memo.patch --]
[-- Type: text/x-patch; name=0001-Fix-Building-the-event-list-fails-on-fragmented-memo.patch, Size: 3131 bytes --]

From 24951859b58a06b8867165ce4857346535d3dc73 Mon Sep 17 00:00:00 2001
From: Martin Leisener <martin@leisener.de>
Date: Wed, 10 Jun 2015 15:17:37 +0200
Subject: [PATCH] Fix: Building the event list fails on fragmented memory

On a small arm imx6 solo with 256MB RAM it often happens that memory
becomes fragmented rather quickly, so that kmalloc will not be able to
get enough consecutive pages (enocuntered for example if you enable all
kernel events: lttng enable-event -k syscall --all).

This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu
12.04 Lts and on imx6 solo 256MB RAM

If this patch is not applied, you can identify low and/or fragmented
memory failures by looking at the kernel ring buffer (please ignore DMA,
it is due to some memory setup misconfiguration, should read Normal):

...
[  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
...
[  321.994711] lowmem_reserve[]: 0 0 0
[  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC) 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB 0*16384kB 0*32768kB = 46068kB

[ Edit by Mathieu: use vzalloc() rather than vmalloc() + memset 0. ]

Signed-off-by: Martin Leisener <martin@leisener.de>
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
---
 lttng-events.c | 16 +++++++++++-----
 1 file changed, 11 insertions(+), 5 deletions(-)

diff --git a/lttng-events.c b/lttng-events.c
index 7eec04c..9b63789 100644
--- a/lttng-events.c
+++ b/lttng-events.c
@@ -39,6 +39,7 @@
 #include "wrapper/file.h"
 #include <linux/jhash.h>
 #include <linux/uaccess.h>
+#include <linux/vmalloc.h>
 
 #include "wrapper/uuid.h"
 #include "wrapper/vmalloc.h"	/* for wrapper_vmalloc_sync_all() */
@@ -132,8 +133,7 @@ struct lttng_session *lttng_session_create(void)
 			GFP_KERNEL);
 	if (!metadata_cache)
 		goto err_free_session;
-	metadata_cache->data = kzalloc(METADATA_CACHE_DEFAULT_SIZE,
-			GFP_KERNEL);
+	metadata_cache->data = vzalloc(METADATA_CACHE_DEFAULT_SIZE);
 	if (!metadata_cache->data)
 		goto err_free_cache;
 	metadata_cache->cache_alloc = METADATA_CACHE_DEFAULT_SIZE;
@@ -162,7 +162,7 @@ void metadata_cache_destroy(struct kref *kref)
 {
 	struct lttng_metadata_cache *cache =
 		container_of(kref, struct lttng_metadata_cache, refcount);
-	kfree(cache->data);
+	vfree(cache->data);
 	kfree(cache);
 }
 
@@ -1523,10 +1523,16 @@ int lttng_metadata_printf(struct lttng_session *session,
 		tmp_cache_alloc_size = max_t(unsigned int,
 				session->metadata_cache->cache_alloc + len,
 				session->metadata_cache->cache_alloc << 1);
-		tmp_cache_realloc = krealloc(session->metadata_cache->data,
-				tmp_cache_alloc_size, GFP_KERNEL);
+		tmp_cache_realloc = vzalloc(tmp_cache_alloc_size);
 		if (!tmp_cache_realloc)
 			goto err;
+		if (session->metadata_cache->data) {
+			memcpy(tmp_cache_realloc,
+				session->metadata_cache->data,
+				session->metadata_cache->cache_alloc);
+			vfree(session->metadata_cache->data);
+		}
+
 		session->metadata_cache->cache_alloc = tmp_cache_alloc_size;
 		session->metadata_cache->data = tmp_cache_realloc;
 	}
-- 
1.9.1


[-- Attachment #3: Type: text/plain, Size: 155 bytes --]

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Mathieu Desnoyers]

I think I found the culprit (testing now):

int lttng_metadata_printf(struct lttng_session *session,
                          const char *fmt, ...)

                tmp_cache_alloc_size = max_t(unsigned int,
                                session->metadata_cache->cache_alloc + len,
                                session->metadata_cache->cache_alloc << 1)

should be:

                tmp_cache_alloc_size = max_t(unsigned int,
                                session->metadata_cache->metadata_written + len,
                                session->metadata_cache->cache_alloc << 1);

I think we have a possible memory corruption in the upstream code here.

More coming soon,

Thanks,

Mathieu


----- On Jun 23, 2015, at 3:46 PM, Mathieu Desnoyers mathieu.desnoyers@efficios.com wrote:

> ----- On Jun 23, 2015, at 9:46 AM, Jan Glauber jan.glauber@gmail.com wrote:
> 
>> On Sat, Jun 13, 2015 at 07:32:28PM +0000, Mathieu Desnoyers wrote:
>>> ----- On Jun 10, 2015, at 9:17 AM, Martin Leisener martin@leisener.de wrote:
>>> 
>>> > Hi Mathieu,
>>> > 
>>> > sorry for sending the broken patch, I fell for some "smart" formating of my
>>> > email client, I cannot utilize it myself the way I send it.
>>> > Hence I now send the patch again as it was original intended. Sent to myself, I
>>> > can apply it, so I hope it now works in general as well
>>> > I examined as recommended diff -urN, it seems the output can be utilized by
>>> > patch the same way as git diff.
>>> > Hope it is now received the way I intended.
>>> 
>>> Hi Martin,
>>> 
>>> I tried you patch on a x86-64 machine (my laptop), and although taking a
>>> single kernel trace worked fine, it appears to OOPS when I run
>>> 
>>> (in lttng-tools)
>>> cd tests
>>> ./run.sh root_regression
>> 
>> Hi Mathieu,
>> 
>> can you please share the oops message so I can have a look?
> 
> Sure,
> 
> Here is the backtrace happening with the attached patch over lttng-modules
> commit 8c6e7f13c778701dec2d6549f1e2ca98970907a0. I modified your patch
> slightly.
> 
> [ 4078.314978] BUG: unable to handle kernel paging request at ffffc900038d995e
> [ 4078.315824] IP: [<ffffffff81316f12>] __memcpy+0x12/0x20
> [ 4078.315824] PGD 236c92067 PUD 236c93067 PMD bac0c067 PTE 0
> [ 4078.315824] Oops: 0000 [#1] SMP
> [ 4078.315824] Modules linked in: lttng_probe_workqueue(O) lttng_probe_vmscan(O)
> lttng_probe_udp(O) lttng_probe_timer(O) lttng_probe_sunrpc(O)
> lttng_probe_statedump(O) lttng_probe_sock(O) lttng_probe_skb(O)
> lttng_probe_signal(O) lttng_probe_scsi(O) lttng_probe_sched(O)
> lttng_probe_regmap(O) lttng_probe_rcu(O) lttng_probe_random(O)
> lttng_probe_printk(O) lttng_probe_power(O) lttng_probe_net(O)
> lttng_probe_napi(O) lttng_probe_module(O) lttng_probe_kmem(O)
> lttng_probe_jbd2(O) lttng_probe_irq(O) lttng_probe_ext4(O)
> lttng_probe_compaction(O) lttng_probe_block(O) lttng_types(O)
> lttng_ring_buffer_metadata_mmap_client(O)
> lttng_ring_buffer_client_mmap_overwrite(O)
> lttng_ring_buffer_client_mmap_discard(O) lttng_ring_buffer_metadata_client(O)
> lttng_ring_buffer_client_overwrite(O) lttng_ring_buffer_client_discard(O)
> lttng_tracer(O) lttng_statedump(O) lttng_kprobes(O) lttng_lib_ring_buffer(O)
> lttng_kretprobes(O) virtio_blk virtio_net virtio_pci virtio_ring virtio
> [ 4078.315824] CPU: 5 PID: 4258 Comm: lttng-consumerd Tainted: G           O
> 4.1.0 #7
> [ 4078.315824] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs
> 01/01/2011
> [ 4078.315824] task: ffff8802350c3660 ti: ffff8800bae84000 task.ti:
> ffff8800bae84000
> [ 4078.315824] RIP: 0010:[<ffffffff81316f12>]  [<ffffffff81316f12>]
> __memcpy+0x12/0x20
> [ 4078.315824] RSP: 0018:ffff8800bae87da0  EFLAGS: 00010246
> [ 4078.315824] RAX: ffff880235439025 RBX: 0000000000000fd8 RCX: 00000000000001fb
> [ 4078.315824] RDX: 0000000000000000 RSI: ffffc900038d995e RDI: ffff880235439025
> [ 4078.315824] RBP: ffff8800bae87db8 R08: ffff8800bacecc00 R09: 0000000000008000
> [ 4078.315824] R10: 0000000000000000 R11: 0000000000000246 R12: ffff8800bae87dc8
> [ 4078.315824] R13: ffff88023466e800 R14: 0000000000000fd8 R15: 0000000000000fd8
> [ 4078.315824] FS:  00007f5d3b1cc700(0000) GS:ffff8802372a0000(0000)
> knlGS:0000000000000000
> [ 4078.315824] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [ 4078.315824] CR2: ffffc900038d995e CR3: 00000000bb1ed000 CR4: 00000000000006e0
> [ 4078.315824] Stack:
> [ 4078.315824]  ffffffffa01ac797 ffff8800bb5bd480 ffff8800bb5bd4d0
> ffff8800bae87e48
> [ 4078.315824]  ffffffffa0073060 ffff88023466e800 0000000000000000
> 0000000000000fd8
> [ 4078.315824]  ffffffff00000001 ffff8800bacecc00 0000000000000fd8
> 0000000000008025
> [ 4078.315824] Call Trace:
> [ 4078.315824]  [<ffffffffa01ac797>] ? lttng_event_write+0x87/0xb0
> [lttng_ring_buffer_metadata_client]
> [ 4078.315824]  [<ffffffffa0073060>] lttng_metadata_output_channel+0xd0/0x120
> [lttng_tracer]
> [ 4078.315824]  [<ffffffffa00755f9>] lttng_metadata_ring_buffer_ioctl+0x79/0xd0
> [lttng_tracer]
> [ 4078.315824]  [<ffffffff8117ba10>] do_vfs_ioctl+0x2e0/0x4e0
> [ 4078.315824]  [<ffffffff812b35c7>] ? file_has_perm+0x87/0xa0
> [ 4078.315824]  [<ffffffff8117bc91>] SyS_ioctl+0x81/0xa0
> [ 4078.315824]  [<ffffffff810115d1>] ? syscall_trace_leave+0xd1/0xe0
> [ 4078.315824]  [<ffffffff818bbd37>] tracesys_phase2+0x84/0x89
> [ 4078.315824] Code: 5b 5d c3 66 0f 1f 44 00 00 e8 6b fc ff ff eb e1 90 90 90 90
> 90 90 90 90 90 0f 1f 44 00 00 48 89 f8 48 89 d1 48 c1 e9 03 83 e2 07 <f3> 48 a5
> 89 d1 f3 a4 c3 66 0f 1f 44 00 00 48 89 f8 48 89 d1 f3
> [ 4078.315824] RIP  [<ffffffff81316f12>] __memcpy+0x12/0x20
> [ 4078.315824]  RSP <ffff8800bae87da0>
> [ 4078.315824] CR2: ffffc900038d995e
> [ 4078.315824] ---[ end trace a05b652829ceda48 ]---
> [ 4078.433848] LTTng: block device enumeration is not supported by kernel
> 
> 
> --
> Mathieu Desnoyers
> EfficiOS Inc.
> http://www.efficios.com
> _______________________________________________
> lttng-dev mailing list
> lttng-dev@lists.lttng.org
> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Mathieu Desnoyers]

Nope, it wasn't it. metadata_written is always <= cache_alloc, so the
current upstream code looks correct.

I've just tried after changing the CPU configuration from "hypervisor
default" to "copy host cpu config" on my machine, and was then unable
to reproduce. I wonder if there is not an issue with __memcpy implementation
for specific x86_64 processors (e.g. reading too many bytes from the vmalloc'd
area).

Thoughts ?

Thanks,

Mathieu

----- On Jun 23, 2015, at 4:21 PM, Mathieu Desnoyers mathieu.desnoyers@efficios.com wrote:

> I think I found the culprit (testing now):
> 
> int lttng_metadata_printf(struct lttng_session *session,
>                          const char *fmt, ...)
> 
>                tmp_cache_alloc_size = max_t(unsigned int,
>                                session->metadata_cache->cache_alloc + len,
>                                session->metadata_cache->cache_alloc << 1)
> 
> should be:
> 
>                tmp_cache_alloc_size = max_t(unsigned int,
>                                session->metadata_cache->metadata_written + len,
>                                session->metadata_cache->cache_alloc << 1);
> 
> I think we have a possible memory corruption in the upstream code here.
> 
> More coming soon,
> 
> Thanks,
> 
> Mathieu
> 
> 
> ----- On Jun 23, 2015, at 3:46 PM, Mathieu Desnoyers
> mathieu.desnoyers@efficios.com wrote:
> 
>> ----- On Jun 23, 2015, at 9:46 AM, Jan Glauber jan.glauber@gmail.com wrote:
>> 
>>> On Sat, Jun 13, 2015 at 07:32:28PM +0000, Mathieu Desnoyers wrote:
>>>> ----- On Jun 10, 2015, at 9:17 AM, Martin Leisener martin@leisener.de wrote:
>>>> 
>>>> > Hi Mathieu,
>>>> > 
>>>> > sorry for sending the broken patch, I fell for some "smart" formating of my
>>>> > email client, I cannot utilize it myself the way I send it.
>>>> > Hence I now send the patch again as it was original intended. Sent to myself, I
>>>> > can apply it, so I hope it now works in general as well
>>>> > I examined as recommended diff -urN, it seems the output can be utilized by
>>>> > patch the same way as git diff.
>>>> > Hope it is now received the way I intended.
>>>> 
>>>> Hi Martin,
>>>> 
>>>> I tried you patch on a x86-64 machine (my laptop), and although taking a
>>>> single kernel trace worked fine, it appears to OOPS when I run
>>>> 
>>>> (in lttng-tools)
>>>> cd tests
>>>> ./run.sh root_regression
>>> 
>>> Hi Mathieu,
>>> 
>>> can you please share the oops message so I can have a look?
>> 
>> Sure,
>> 
>> Here is the backtrace happening with the attached patch over lttng-modules
>> commit 8c6e7f13c778701dec2d6549f1e2ca98970907a0. I modified your patch
>> slightly.
>> 
>> [ 4078.314978] BUG: unable to handle kernel paging request at ffffc900038d995e
>> [ 4078.315824] IP: [<ffffffff81316f12>] __memcpy+0x12/0x20
>> [ 4078.315824] PGD 236c92067 PUD 236c93067 PMD bac0c067 PTE 0
>> [ 4078.315824] Oops: 0000 [#1] SMP
>> [ 4078.315824] Modules linked in: lttng_probe_workqueue(O) lttng_probe_vmscan(O)
>> lttng_probe_udp(O) lttng_probe_timer(O) lttng_probe_sunrpc(O)
>> lttng_probe_statedump(O) lttng_probe_sock(O) lttng_probe_skb(O)
>> lttng_probe_signal(O) lttng_probe_scsi(O) lttng_probe_sched(O)
>> lttng_probe_regmap(O) lttng_probe_rcu(O) lttng_probe_random(O)
>> lttng_probe_printk(O) lttng_probe_power(O) lttng_probe_net(O)
>> lttng_probe_napi(O) lttng_probe_module(O) lttng_probe_kmem(O)
>> lttng_probe_jbd2(O) lttng_probe_irq(O) lttng_probe_ext4(O)
>> lttng_probe_compaction(O) lttng_probe_block(O) lttng_types(O)
>> lttng_ring_buffer_metadata_mmap_client(O)
>> lttng_ring_buffer_client_mmap_overwrite(O)
>> lttng_ring_buffer_client_mmap_discard(O) lttng_ring_buffer_metadata_client(O)
>> lttng_ring_buffer_client_overwrite(O) lttng_ring_buffer_client_discard(O)
>> lttng_tracer(O) lttng_statedump(O) lttng_kprobes(O) lttng_lib_ring_buffer(O)
>> lttng_kretprobes(O) virtio_blk virtio_net virtio_pci virtio_ring virtio
>> [ 4078.315824] CPU: 5 PID: 4258 Comm: lttng-consumerd Tainted: G           O
>> 4.1.0 #7
>> [ 4078.315824] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs
>> 01/01/2011
>> [ 4078.315824] task: ffff8802350c3660 ti: ffff8800bae84000 task.ti:
>> ffff8800bae84000
>> [ 4078.315824] RIP: 0010:[<ffffffff81316f12>]  [<ffffffff81316f12>]
>> __memcpy+0x12/0x20
>> [ 4078.315824] RSP: 0018:ffff8800bae87da0  EFLAGS: 00010246
>> [ 4078.315824] RAX: ffff880235439025 RBX: 0000000000000fd8 RCX: 00000000000001fb
>> [ 4078.315824] RDX: 0000000000000000 RSI: ffffc900038d995e RDI: ffff880235439025
>> [ 4078.315824] RBP: ffff8800bae87db8 R08: ffff8800bacecc00 R09: 0000000000008000
>> [ 4078.315824] R10: 0000000000000000 R11: 0000000000000246 R12: ffff8800bae87dc8
>> [ 4078.315824] R13: ffff88023466e800 R14: 0000000000000fd8 R15: 0000000000000fd8
>> [ 4078.315824] FS:  00007f5d3b1cc700(0000) GS:ffff8802372a0000(0000)
>> knlGS:0000000000000000
>> [ 4078.315824] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
>> [ 4078.315824] CR2: ffffc900038d995e CR3: 00000000bb1ed000 CR4: 00000000000006e0
>> [ 4078.315824] Stack:
>> [ 4078.315824]  ffffffffa01ac797 ffff8800bb5bd480 ffff8800bb5bd4d0
>> ffff8800bae87e48
>> [ 4078.315824]  ffffffffa0073060 ffff88023466e800 0000000000000000
>> 0000000000000fd8
>> [ 4078.315824]  ffffffff00000001 ffff8800bacecc00 0000000000000fd8
>> 0000000000008025
>> [ 4078.315824] Call Trace:
>> [ 4078.315824]  [<ffffffffa01ac797>] ? lttng_event_write+0x87/0xb0
>> [lttng_ring_buffer_metadata_client]
>> [ 4078.315824]  [<ffffffffa0073060>] lttng_metadata_output_channel+0xd0/0x120
>> [lttng_tracer]
>> [ 4078.315824]  [<ffffffffa00755f9>] lttng_metadata_ring_buffer_ioctl+0x79/0xd0
>> [lttng_tracer]
>> [ 4078.315824]  [<ffffffff8117ba10>] do_vfs_ioctl+0x2e0/0x4e0
>> [ 4078.315824]  [<ffffffff812b35c7>] ? file_has_perm+0x87/0xa0
>> [ 4078.315824]  [<ffffffff8117bc91>] SyS_ioctl+0x81/0xa0
>> [ 4078.315824]  [<ffffffff810115d1>] ? syscall_trace_leave+0xd1/0xe0
>> [ 4078.315824]  [<ffffffff818bbd37>] tracesys_phase2+0x84/0x89
>> [ 4078.315824] Code: 5b 5d c3 66 0f 1f 44 00 00 e8 6b fc ff ff eb e1 90 90 90 90
>> 90 90 90 90 90 0f 1f 44 00 00 48 89 f8 48 89 d1 48 c1 e9 03 83 e2 07 <f3> 48 a5
>> 89 d1 f3 a4 c3 66 0f 1f 44 00 00 48 89 f8 48 89 d1 f3
>> [ 4078.315824] RIP  [<ffffffff81316f12>] __memcpy+0x12/0x20
>> [ 4078.315824]  RSP <ffff8800bae87da0>
>> [ 4078.315824] CR2: ffffc900038d995e
>> [ 4078.315824] ---[ end trace a05b652829ceda48 ]---
>> [ 4078.433848] LTTng: block device enumeration is not supported by kernel
>> 
>> 
>> --
>> Mathieu Desnoyers
>> EfficiOS Inc.
>> http://www.efficios.com
>> _______________________________________________
>> lttng-dev mailing list
>> lttng-dev@lists.lttng.org
>> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
> 
> --
> Mathieu Desnoyers
> EfficiOS Inc.
> http://www.efficios.com
> 
> _______________________________________________
> lttng-dev mailing list
> lttng-dev@lists.lttng.org
> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Jan Glauber]

On Tue, Jun 23, 2015 at 09:04:18PM +0000, Mathieu Desnoyers wrote:
> Nope, it wasn't it. metadata_written is always <= cache_alloc, so the
> current upstream code looks correct.
> 
> I've just tried after changing the CPU configuration from "hypervisor
> default" to "copy host cpu config" on my machine, and was then unable
> to reproduce. I wonder if there is not an issue with __memcpy implementation
> for specific x86_64 processors (e.g. reading too many bytes from the vmalloc'd
> area).
> 
> Thoughts ?

Just speculation without further debugging data from the hypervisor setup
where it fails...

From my understanding memcpy should work regardless of kmalloc or
vmalloc.

Maybe the length parameter of the memcpy is wrong?
With kmalloc and the 1:1 mapping this wont matter but if the memcpy
crosses a page it might fault if the next page is not vmalloc'ed.

But the fault address ffffc900038d995e looks more like src is completely
messed up.

What is the difference between the CPU configurations you tried?

Regards, Jan


> Thanks,
> 
> Mathieu
> 
> ----- On Jun 23, 2015, at 4:21 PM, Mathieu Desnoyers mathieu.desnoyers@efficios.com wrote:
> 
> > I think I found the culprit (testing now):
> > 
> > int lttng_metadata_printf(struct lttng_session *session,
> >                          const char *fmt, ...)
> > 
> >                tmp_cache_alloc_size = max_t(unsigned int,
> >                                session->metadata_cache->cache_alloc + len,
> >                                session->metadata_cache->cache_alloc << 1)
> > 
> > should be:
> > 
> >                tmp_cache_alloc_size = max_t(unsigned int,
> >                                session->metadata_cache->metadata_written + len,
> >                                session->metadata_cache->cache_alloc << 1);
> > 
> > I think we have a possible memory corruption in the upstream code here.
> > 
> > More coming soon,
> > 
> > Thanks,
> > 
> > Mathieu
> > 
> > 
> > ----- On Jun 23, 2015, at 3:46 PM, Mathieu Desnoyers
> > mathieu.desnoyers@efficios.com wrote:
> > 
> >> ----- On Jun 23, 2015, at 9:46 AM, Jan Glauber jan.glauber@gmail.com wrote:
> >> 
> >>> On Sat, Jun 13, 2015 at 07:32:28PM +0000, Mathieu Desnoyers wrote:
> >>>> ----- On Jun 10, 2015, at 9:17 AM, Martin Leisener martin@leisener.de wrote:
> >>>> 
> >>>> > Hi Mathieu,
> >>>> > 
> >>>> > sorry for sending the broken patch, I fell for some "smart" formating of my
> >>>> > email client, I cannot utilize it myself the way I send it.
> >>>> > Hence I now send the patch again as it was original intended. Sent to myself, I
> >>>> > can apply it, so I hope it now works in general as well
> >>>> > I examined as recommended diff -urN, it seems the output can be utilized by
> >>>> > patch the same way as git diff.
> >>>> > Hope it is now received the way I intended.
> >>>> 
> >>>> Hi Martin,
> >>>> 
> >>>> I tried you patch on a x86-64 machine (my laptop), and although taking a
> >>>> single kernel trace worked fine, it appears to OOPS when I run
> >>>> 
> >>>> (in lttng-tools)
> >>>> cd tests
> >>>> ./run.sh root_regression
> >>> 
> >>> Hi Mathieu,
> >>> 
> >>> can you please share the oops message so I can have a look?
> >> 
> >> Sure,
> >> 
> >> Here is the backtrace happening with the attached patch over lttng-modules
> >> commit 8c6e7f13c778701dec2d6549f1e2ca98970907a0. I modified your patch
> >> slightly.
> >> 
> >> [ 4078.314978] BUG: unable to handle kernel paging request at ffffc900038d995e
> >> [ 4078.315824] IP: [<ffffffff81316f12>] __memcpy+0x12/0x20
> >> [ 4078.315824] PGD 236c92067 PUD 236c93067 PMD bac0c067 PTE 0
> >> [ 4078.315824] Oops: 0000 [#1] SMP
> >> [ 4078.315824] Modules linked in: lttng_probe_workqueue(O) lttng_probe_vmscan(O)
> >> lttng_probe_udp(O) lttng_probe_timer(O) lttng_probe_sunrpc(O)
> >> lttng_probe_statedump(O) lttng_probe_sock(O) lttng_probe_skb(O)
> >> lttng_probe_signal(O) lttng_probe_scsi(O) lttng_probe_sched(O)
> >> lttng_probe_regmap(O) lttng_probe_rcu(O) lttng_probe_random(O)
> >> lttng_probe_printk(O) lttng_probe_power(O) lttng_probe_net(O)
> >> lttng_probe_napi(O) lttng_probe_module(O) lttng_probe_kmem(O)
> >> lttng_probe_jbd2(O) lttng_probe_irq(O) lttng_probe_ext4(O)
> >> lttng_probe_compaction(O) lttng_probe_block(O) lttng_types(O)
> >> lttng_ring_buffer_metadata_mmap_client(O)
> >> lttng_ring_buffer_client_mmap_overwrite(O)
> >> lttng_ring_buffer_client_mmap_discard(O) lttng_ring_buffer_metadata_client(O)
> >> lttng_ring_buffer_client_overwrite(O) lttng_ring_buffer_client_discard(O)
> >> lttng_tracer(O) lttng_statedump(O) lttng_kprobes(O) lttng_lib_ring_buffer(O)
> >> lttng_kretprobes(O) virtio_blk virtio_net virtio_pci virtio_ring virtio
> >> [ 4078.315824] CPU: 5 PID: 4258 Comm: lttng-consumerd Tainted: G           O
> >> 4.1.0 #7
> >> [ 4078.315824] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs
> >> 01/01/2011
> >> [ 4078.315824] task: ffff8802350c3660 ti: ffff8800bae84000 task.ti:
> >> ffff8800bae84000
> >> [ 4078.315824] RIP: 0010:[<ffffffff81316f12>]  [<ffffffff81316f12>]
> >> __memcpy+0x12/0x20
> >> [ 4078.315824] RSP: 0018:ffff8800bae87da0  EFLAGS: 00010246
> >> [ 4078.315824] RAX: ffff880235439025 RBX: 0000000000000fd8 RCX: 00000000000001fb
> >> [ 4078.315824] RDX: 0000000000000000 RSI: ffffc900038d995e RDI: ffff880235439025
> >> [ 4078.315824] RBP: ffff8800bae87db8 R08: ffff8800bacecc00 R09: 0000000000008000
> >> [ 4078.315824] R10: 0000000000000000 R11: 0000000000000246 R12: ffff8800bae87dc8
> >> [ 4078.315824] R13: ffff88023466e800 R14: 0000000000000fd8 R15: 0000000000000fd8
> >> [ 4078.315824] FS:  00007f5d3b1cc700(0000) GS:ffff8802372a0000(0000)
> >> knlGS:0000000000000000
> >> [ 4078.315824] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> >> [ 4078.315824] CR2: ffffc900038d995e CR3: 00000000bb1ed000 CR4: 00000000000006e0
> >> [ 4078.315824] Stack:
> >> [ 4078.315824]  ffffffffa01ac797 ffff8800bb5bd480 ffff8800bb5bd4d0
> >> ffff8800bae87e48
> >> [ 4078.315824]  ffffffffa0073060 ffff88023466e800 0000000000000000
> >> 0000000000000fd8
> >> [ 4078.315824]  ffffffff00000001 ffff8800bacecc00 0000000000000fd8
> >> 0000000000008025
> >> [ 4078.315824] Call Trace:
> >> [ 4078.315824]  [<ffffffffa01ac797>] ? lttng_event_write+0x87/0xb0
> >> [lttng_ring_buffer_metadata_client]
> >> [ 4078.315824]  [<ffffffffa0073060>] lttng_metadata_output_channel+0xd0/0x120
> >> [lttng_tracer]
> >> [ 4078.315824]  [<ffffffffa00755f9>] lttng_metadata_ring_buffer_ioctl+0x79/0xd0
> >> [lttng_tracer]
> >> [ 4078.315824]  [<ffffffff8117ba10>] do_vfs_ioctl+0x2e0/0x4e0
> >> [ 4078.315824]  [<ffffffff812b35c7>] ? file_has_perm+0x87/0xa0
> >> [ 4078.315824]  [<ffffffff8117bc91>] SyS_ioctl+0x81/0xa0
> >> [ 4078.315824]  [<ffffffff810115d1>] ? syscall_trace_leave+0xd1/0xe0
> >> [ 4078.315824]  [<ffffffff818bbd37>] tracesys_phase2+0x84/0x89
> >> [ 4078.315824] Code: 5b 5d c3 66 0f 1f 44 00 00 e8 6b fc ff ff eb e1 90 90 90 90
> >> 90 90 90 90 90 0f 1f 44 00 00 48 89 f8 48 89 d1 48 c1 e9 03 83 e2 07 <f3> 48 a5
> >> 89 d1 f3 a4 c3 66 0f 1f 44 00 00 48 89 f8 48 89 d1 f3
> >> [ 4078.315824] RIP  [<ffffffff81316f12>] __memcpy+0x12/0x20
> >> [ 4078.315824]  RSP <ffff8800bae87da0>
> >> [ 4078.315824] CR2: ffffc900038d995e
> >> [ 4078.315824] ---[ end trace a05b652829ceda48 ]---
> >> [ 4078.433848] LTTng: block device enumeration is not supported by kernel
> >> 
> >> 
> >> --
> >> Mathieu Desnoyers
> >> EfficiOS Inc.
> >> http://www.efficios.com
> >> _______________________________________________
> >> lttng-dev mailing list
> >> lttng-dev@lists.lttng.org
> >> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
> > 
> > --
> > Mathieu Desnoyers
> > EfficiOS Inc.
> > http://www.efficios.com
> > 
> > _______________________________________________
> > lttng-dev mailing list
> > lttng-dev@lists.lttng.org
> > http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
> 
> -- 
> Mathieu Desnoyers
> EfficiOS Inc.
> http://www.efficios.com

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Mathieu Desnoyers]

----- On Jun 25, 2015, at 4:08 AM, Jan Glauber jan.glauber@gmail.com wrote:

> On Tue, Jun 23, 2015 at 09:04:18PM +0000, Mathieu Desnoyers wrote:
>> Nope, it wasn't it. metadata_written is always <= cache_alloc, so the
>> current upstream code looks correct.
>> 
>> I've just tried after changing the CPU configuration from "hypervisor
>> default" to "copy host cpu config" on my machine, and was then unable
>> to reproduce. I wonder if there is not an issue with __memcpy implementation
>> for specific x86_64 processors (e.g. reading too many bytes from the vmalloc'd
>> area).
>> 
>> Thoughts ?
> 
> Just speculation without further debugging data from the hypervisor setup
> where it fails...
> 
> From my understanding memcpy should work regardless of kmalloc or
> vmalloc.
> 
> Maybe the length parameter of the memcpy is wrong?
> With kmalloc and the 1:1 mapping this wont matter but if the memcpy
> crosses a page it might fault if the next page is not vmalloc'ed.
> 
> But the fault address ffffc900038d995e looks more like src is completely
> messed up.
> 
> What is the difference between the CPU configurations you tried?

Actually, I just narrowed it down to a missing mutex around the metadata
cache accesses. The updater can reallocate the memory, and the reader
(which outputs from the cache to a ring buffer) assumes that it does not
have to lock the metadata cache because it only reads its content.
Unfortunately, this does not take into account that the memory backing
the cache can be reallocated.

I'll prepare a fix.

Thanks!

Mathieu


> 
> Regards, Jan
> 
> 
>> Thanks,
>> 
>> Mathieu
>> 
>> ----- On Jun 23, 2015, at 4:21 PM, Mathieu Desnoyers
>> mathieu.desnoyers@efficios.com wrote:
>> 
>> > I think I found the culprit (testing now):
>> > 
>> > int lttng_metadata_printf(struct lttng_session *session,
>> >                          const char *fmt, ...)
>> > 
>> >                tmp_cache_alloc_size = max_t(unsigned int,
>> >                                session->metadata_cache->cache_alloc + len,
>> >                                session->metadata_cache->cache_alloc << 1)
>> > 
>> > should be:
>> > 
>> >                tmp_cache_alloc_size = max_t(unsigned int,
>> >                                session->metadata_cache->metadata_written + len,
>> >                                session->metadata_cache->cache_alloc << 1);
>> > 
>> > I think we have a possible memory corruption in the upstream code here.
>> > 
>> > More coming soon,
>> > 
>> > Thanks,
>> > 
>> > Mathieu
>> > 
>> > 
>> > ----- On Jun 23, 2015, at 3:46 PM, Mathieu Desnoyers
>> > mathieu.desnoyers@efficios.com wrote:
>> > 
>> >> ----- On Jun 23, 2015, at 9:46 AM, Jan Glauber jan.glauber@gmail.com wrote:
>> >> 
>> >>> On Sat, Jun 13, 2015 at 07:32:28PM +0000, Mathieu Desnoyers wrote:
>> >>>> ----- On Jun 10, 2015, at 9:17 AM, Martin Leisener martin@leisener.de wrote:
>> >>>> 
>> >>>> > Hi Mathieu,
>> >>>> > 
>> >>>> > sorry for sending the broken patch, I fell for some "smart" formating of my
>> >>>> > email client, I cannot utilize it myself the way I send it.
>> >>>> > Hence I now send the patch again as it was original intended. Sent to myself, I
>> >>>> > can apply it, so I hope it now works in general as well
>> >>>> > I examined as recommended diff -urN, it seems the output can be utilized by
>> >>>> > patch the same way as git diff.
>> >>>> > Hope it is now received the way I intended.
>> >>>> 
>> >>>> Hi Martin,
>> >>>> 
>> >>>> I tried you patch on a x86-64 machine (my laptop), and although taking a
>> >>>> single kernel trace worked fine, it appears to OOPS when I run
>> >>>> 
>> >>>> (in lttng-tools)
>> >>>> cd tests
>> >>>> ./run.sh root_regression
>> >>> 
>> >>> Hi Mathieu,
>> >>> 
>> >>> can you please share the oops message so I can have a look?
>> >> 
>> >> Sure,
>> >> 
>> >> Here is the backtrace happening with the attached patch over lttng-modules
>> >> commit 8c6e7f13c778701dec2d6549f1e2ca98970907a0. I modified your patch
>> >> slightly.
>> >> 
>> >> [ 4078.314978] BUG: unable to handle kernel paging request at ffffc900038d995e
>> >> [ 4078.315824] IP: [<ffffffff81316f12>] __memcpy+0x12/0x20
>> >> [ 4078.315824] PGD 236c92067 PUD 236c93067 PMD bac0c067 PTE 0
>> >> [ 4078.315824] Oops: 0000 [#1] SMP
>> >> [ 4078.315824] Modules linked in: lttng_probe_workqueue(O) lttng_probe_vmscan(O)
>> >> lttng_probe_udp(O) lttng_probe_timer(O) lttng_probe_sunrpc(O)
>> >> lttng_probe_statedump(O) lttng_probe_sock(O) lttng_probe_skb(O)
>> >> lttng_probe_signal(O) lttng_probe_scsi(O) lttng_probe_sched(O)
>> >> lttng_probe_regmap(O) lttng_probe_rcu(O) lttng_probe_random(O)
>> >> lttng_probe_printk(O) lttng_probe_power(O) lttng_probe_net(O)
>> >> lttng_probe_napi(O) lttng_probe_module(O) lttng_probe_kmem(O)
>> >> lttng_probe_jbd2(O) lttng_probe_irq(O) lttng_probe_ext4(O)
>> >> lttng_probe_compaction(O) lttng_probe_block(O) lttng_types(O)
>> >> lttng_ring_buffer_metadata_mmap_client(O)
>> >> lttng_ring_buffer_client_mmap_overwrite(O)
>> >> lttng_ring_buffer_client_mmap_discard(O) lttng_ring_buffer_metadata_client(O)
>> >> lttng_ring_buffer_client_overwrite(O) lttng_ring_buffer_client_discard(O)
>> >> lttng_tracer(O) lttng_statedump(O) lttng_kprobes(O) lttng_lib_ring_buffer(O)
>> >> lttng_kretprobes(O) virtio_blk virtio_net virtio_pci virtio_ring virtio
>> >> [ 4078.315824] CPU: 5 PID: 4258 Comm: lttng-consumerd Tainted: G           O
>> >> 4.1.0 #7
>> >> [ 4078.315824] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs
>> >> 01/01/2011
>> >> [ 4078.315824] task: ffff8802350c3660 ti: ffff8800bae84000 task.ti:
>> >> ffff8800bae84000
>> >> [ 4078.315824] RIP: 0010:[<ffffffff81316f12>]  [<ffffffff81316f12>]
>> >> __memcpy+0x12/0x20
>> >> [ 4078.315824] RSP: 0018:ffff8800bae87da0  EFLAGS: 00010246
>> >> [ 4078.315824] RAX: ffff880235439025 RBX: 0000000000000fd8 RCX: 00000000000001fb
>> >> [ 4078.315824] RDX: 0000000000000000 RSI: ffffc900038d995e RDI: ffff880235439025
>> >> [ 4078.315824] RBP: ffff8800bae87db8 R08: ffff8800bacecc00 R09: 0000000000008000
>> >> [ 4078.315824] R10: 0000000000000000 R11: 0000000000000246 R12: ffff8800bae87dc8
>> >> [ 4078.315824] R13: ffff88023466e800 R14: 0000000000000fd8 R15: 0000000000000fd8
>> >> [ 4078.315824] FS:  00007f5d3b1cc700(0000) GS:ffff8802372a0000(0000)
>> >> knlGS:0000000000000000
>> >> [ 4078.315824] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
>> >> [ 4078.315824] CR2: ffffc900038d995e CR3: 00000000bb1ed000 CR4: 00000000000006e0
>> >> [ 4078.315824] Stack:
>> >> [ 4078.315824]  ffffffffa01ac797 ffff8800bb5bd480 ffff8800bb5bd4d0
>> >> ffff8800bae87e48
>> >> [ 4078.315824]  ffffffffa0073060 ffff88023466e800 0000000000000000
>> >> 0000000000000fd8
>> >> [ 4078.315824]  ffffffff00000001 ffff8800bacecc00 0000000000000fd8
>> >> 0000000000008025
>> >> [ 4078.315824] Call Trace:
>> >> [ 4078.315824]  [<ffffffffa01ac797>] ? lttng_event_write+0x87/0xb0
>> >> [lttng_ring_buffer_metadata_client]
>> >> [ 4078.315824]  [<ffffffffa0073060>] lttng_metadata_output_channel+0xd0/0x120
>> >> [lttng_tracer]
>> >> [ 4078.315824]  [<ffffffffa00755f9>] lttng_metadata_ring_buffer_ioctl+0x79/0xd0
>> >> [lttng_tracer]
>> >> [ 4078.315824]  [<ffffffff8117ba10>] do_vfs_ioctl+0x2e0/0x4e0
>> >> [ 4078.315824]  [<ffffffff812b35c7>] ? file_has_perm+0x87/0xa0
>> >> [ 4078.315824]  [<ffffffff8117bc91>] SyS_ioctl+0x81/0xa0
>> >> [ 4078.315824]  [<ffffffff810115d1>] ? syscall_trace_leave+0xd1/0xe0
>> >> [ 4078.315824]  [<ffffffff818bbd37>] tracesys_phase2+0x84/0x89
>> >> [ 4078.315824] Code: 5b 5d c3 66 0f 1f 44 00 00 e8 6b fc ff ff eb e1 90 90 90 90
>> >> 90 90 90 90 90 0f 1f 44 00 00 48 89 f8 48 89 d1 48 c1 e9 03 83 e2 07 <f3> 48 a5
>> >> 89 d1 f3 a4 c3 66 0f 1f 44 00 00 48 89 f8 48 89 d1 f3
>> >> [ 4078.315824] RIP  [<ffffffff81316f12>] __memcpy+0x12/0x20
>> >> [ 4078.315824]  RSP <ffff8800bae87da0>
>> >> [ 4078.315824] CR2: ffffc900038d995e
>> >> [ 4078.315824] ---[ end trace a05b652829ceda48 ]---
>> >> [ 4078.433848] LTTng: block device enumeration is not supported by kernel
>> >> 
>> >> 
>> >> --
>> >> Mathieu Desnoyers
>> >> EfficiOS Inc.
>> >> http://www.efficios.com
>> >> _______________________________________________
>> >> lttng-dev mailing list
>> >> lttng-dev@lists.lttng.org
>> >> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
>> > 
>> > --
>> > Mathieu Desnoyers
>> > EfficiOS Inc.
>> > http://www.efficios.com
>> > 
>> > _______________________________________________
>> > lttng-dev mailing list
>> > lttng-dev@lists.lttng.org
>> > http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
>> 
>> --
>> Mathieu Desnoyers
>> EfficiOS Inc.
> > http://www.efficios.com

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Mathieu Desnoyers]

----- On Jun 25, 2015, at 9:00 AM, Mathieu Desnoyers mathieu.desnoyers@efficios.com wrote:

> ----- On Jun 25, 2015, at 4:08 AM, Jan Glauber jan.glauber@gmail.com wrote:
> 
>> On Tue, Jun 23, 2015 at 09:04:18PM +0000, Mathieu Desnoyers wrote:
>>> Nope, it wasn't it. metadata_written is always <= cache_alloc, so the
>>> current upstream code looks correct.
>>> 
>>> I've just tried after changing the CPU configuration from "hypervisor
>>> default" to "copy host cpu config" on my machine, and was then unable
>>> to reproduce. I wonder if there is not an issue with __memcpy implementation
>>> for specific x86_64 processors (e.g. reading too many bytes from the vmalloc'd
>>> area).
>>> 
>>> Thoughts ?
>> 
>> Just speculation without further debugging data from the hypervisor setup
>> where it fails...
>> 
>> From my understanding memcpy should work regardless of kmalloc or
>> vmalloc.
>> 
>> Maybe the length parameter of the memcpy is wrong?
>> With kmalloc and the 1:1 mapping this wont matter but if the memcpy
>> crosses a page it might fault if the next page is not vmalloc'ed.
>> 
>> But the fault address ffffc900038d995e looks more like src is completely
>> messed up.
>> 
>> What is the difference between the CPU configurations you tried?
> 
> Actually, I just narrowed it down to a missing mutex around the metadata
> cache accesses. The updater can reallocate the memory, and the reader
> (which outputs from the cache to a ring buffer) assumes that it does not
> have to lock the metadata cache because it only reads its content.
> Unfortunately, this does not take into account that the memory backing
> the cache can be reallocated.
> 
> I'll prepare a fix.

I just pushed the two following commits upstream:

commit a606b6e893b99bc31cacee98415942dbc577c90c
Author: Martin Leisener <martin@leisener.de>
Date:   Wed Jun 10 15:17:37 2015 +0200

    Fix: Building the event list fails on fragmented memory
    
    On a small arm imx6 solo with 256MB RAM it often happens that memory
    becomes fragmented rather quickly, so that kmalloc will not be able to
    get enough consecutive pages (enocuntered for example if you enable all
    kernel events: lttng enable-event -k syscall --all).
    
    This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu
    12.04 Lts and on imx6 solo 256MB RAM
    
    If this patch is not applied, you can identify low and/or fragmented
    memory failures by looking at the kernel ring buffer (please ignore DMA,
    it is due to some memory setup misconfiguration, should read Normal):
    
    ...
    [  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
    ...
    [  321.994711] lowmem_reserve[]: 0 0 0
    [  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC) 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB 0*16384kB 0*32768kB = 46068kB
    
    [ Edit by Mathieu: use vzalloc() rather than vmalloc() + memset 0. ]
    
    Signed-off-by: Martin Leisener <martin@leisener.de>
    Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>

commit 92d9f5e6df0f72842b28ccd303569c88e183325a
Author: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Date:   Thu Jun 25 09:10:52 2015 -0400

    Fix: use after free on metadata cache reallocation
    
    When the metadata cache is expanded (reallocated) by
    lttng_metadata_printf(), the metadata cache reader
    (lttng_metadata_output_channel()) may use freed memory, because the
    metadata cache is not protected from concurrent read accesses. The
    metadata cache updates are protected from each other by the sessions
    mutex, but metadata cache reads do not hold the sessions mutex.
    Actually, the comment on top of lttng_metadata_output_channel() stating
    "We have exclusive access to our metadata buffer (protected by the
    sessions_mutex)" is simply wrong, because this mutex is never held when
    calling lttng_metadata_output_channel().

    Promote the per-stream lock to the metadata cache used by each of those
    metadata streams, thus ensuring mutual exclusion between metadata cache
    reallocation and readers.
    
    Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>


Thanks,

Mathieu

> 
> Thanks!
> 
> Mathieu
> 
> 
>> 
>> Regards, Jan
>> 
>> 
>>> Thanks,
>>> 
>>> Mathieu
>>> 
>>> ----- On Jun 23, 2015, at 4:21 PM, Mathieu Desnoyers
>>> mathieu.desnoyers@efficios.com wrote:
>>> 
>>> > I think I found the culprit (testing now):
>>> > 
>>> > int lttng_metadata_printf(struct lttng_session *session,
>>> >                          const char *fmt, ...)
>>> > 
>>> >                tmp_cache_alloc_size = max_t(unsigned int,
>>> >                                session->metadata_cache->cache_alloc + len,
>>> >                                session->metadata_cache->cache_alloc << 1)
>>> > 
>>> > should be:
>>> > 
>>> >                tmp_cache_alloc_size = max_t(unsigned int,
>>> >                                session->metadata_cache->metadata_written + len,
>>> >                                session->metadata_cache->cache_alloc << 1);
>>> > 
>>> > I think we have a possible memory corruption in the upstream code here.
>>> > 
>>> > More coming soon,
>>> > 
>>> > Thanks,
>>> > 
>>> > Mathieu
>>> > 
>>> > 
>>> > ----- On Jun 23, 2015, at 3:46 PM, Mathieu Desnoyers
>>> > mathieu.desnoyers@efficios.com wrote:
>>> > 
>>> >> ----- On Jun 23, 2015, at 9:46 AM, Jan Glauber jan.glauber@gmail.com wrote:
>>> >> 
>>> >>> On Sat, Jun 13, 2015 at 07:32:28PM +0000, Mathieu Desnoyers wrote:
>>> >>>> ----- On Jun 10, 2015, at 9:17 AM, Martin Leisener martin@leisener.de wrote:
>>> >>>> 
>>> >>>> > Hi Mathieu,
>>> >>>> > 
>>> >>>> > sorry for sending the broken patch, I fell for some "smart" formating of my
>>> >>>> > email client, I cannot utilize it myself the way I send it.
>>> >>>> > Hence I now send the patch again as it was original intended. Sent to myself, I
>>> >>>> > can apply it, so I hope it now works in general as well
>>> >>>> > I examined as recommended diff -urN, it seems the output can be utilized by
>>> >>>> > patch the same way as git diff.
>>> >>>> > Hope it is now received the way I intended.
>>> >>>> 
>>> >>>> Hi Martin,
>>> >>>> 
>>> >>>> I tried you patch on a x86-64 machine (my laptop), and although taking a
>>> >>>> single kernel trace worked fine, it appears to OOPS when I run
>>> >>>> 
>>> >>>> (in lttng-tools)
>>> >>>> cd tests
>>> >>>> ./run.sh root_regression
>>> >>> 
>>> >>> Hi Mathieu,
>>> >>> 
>>> >>> can you please share the oops message so I can have a look?
>>> >> 
>>> >> Sure,
>>> >> 
>>> >> Here is the backtrace happening with the attached patch over lttng-modules
>>> >> commit 8c6e7f13c778701dec2d6549f1e2ca98970907a0. I modified your patch
>>> >> slightly.
>>> >> 
>>> >> [ 4078.314978] BUG: unable to handle kernel paging request at ffffc900038d995e
>>> >> [ 4078.315824] IP: [<ffffffff81316f12>] __memcpy+0x12/0x20
>>> >> [ 4078.315824] PGD 236c92067 PUD 236c93067 PMD bac0c067 PTE 0
>>> >> [ 4078.315824] Oops: 0000 [#1] SMP
>>> >> [ 4078.315824] Modules linked in: lttng_probe_workqueue(O) lttng_probe_vmscan(O)
>>> >> lttng_probe_udp(O) lttng_probe_timer(O) lttng_probe_sunrpc(O)
>>> >> lttng_probe_statedump(O) lttng_probe_sock(O) lttng_probe_skb(O)
>>> >> lttng_probe_signal(O) lttng_probe_scsi(O) lttng_probe_sched(O)
>>> >> lttng_probe_regmap(O) lttng_probe_rcu(O) lttng_probe_random(O)
>>> >> lttng_probe_printk(O) lttng_probe_power(O) lttng_probe_net(O)
>>> >> lttng_probe_napi(O) lttng_probe_module(O) lttng_probe_kmem(O)
>>> >> lttng_probe_jbd2(O) lttng_probe_irq(O) lttng_probe_ext4(O)
>>> >> lttng_probe_compaction(O) lttng_probe_block(O) lttng_types(O)
>>> >> lttng_ring_buffer_metadata_mmap_client(O)
>>> >> lttng_ring_buffer_client_mmap_overwrite(O)
>>> >> lttng_ring_buffer_client_mmap_discard(O) lttng_ring_buffer_metadata_client(O)
>>> >> lttng_ring_buffer_client_overwrite(O) lttng_ring_buffer_client_discard(O)
>>> >> lttng_tracer(O) lttng_statedump(O) lttng_kprobes(O) lttng_lib_ring_buffer(O)
>>> >> lttng_kretprobes(O) virtio_blk virtio_net virtio_pci virtio_ring virtio
>>> >> [ 4078.315824] CPU: 5 PID: 4258 Comm: lttng-consumerd Tainted: G           O
>>> >> 4.1.0 #7
>>> >> [ 4078.315824] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs
>>> >> 01/01/2011
>>> >> [ 4078.315824] task: ffff8802350c3660 ti: ffff8800bae84000 task.ti:
>>> >> ffff8800bae84000
>>> >> [ 4078.315824] RIP: 0010:[<ffffffff81316f12>]  [<ffffffff81316f12>]
>>> >> __memcpy+0x12/0x20
>>> >> [ 4078.315824] RSP: 0018:ffff8800bae87da0  EFLAGS: 00010246
>>> >> [ 4078.315824] RAX: ffff880235439025 RBX: 0000000000000fd8 RCX: 00000000000001fb
>>> >> [ 4078.315824] RDX: 0000000000000000 RSI: ffffc900038d995e RDI: ffff880235439025
>>> >> [ 4078.315824] RBP: ffff8800bae87db8 R08: ffff8800bacecc00 R09: 0000000000008000
>>> >> [ 4078.315824] R10: 0000000000000000 R11: 0000000000000246 R12: ffff8800bae87dc8
>>> >> [ 4078.315824] R13: ffff88023466e800 R14: 0000000000000fd8 R15: 0000000000000fd8
>>> >> [ 4078.315824] FS:  00007f5d3b1cc700(0000) GS:ffff8802372a0000(0000)
>>> >> knlGS:0000000000000000
>>> >> [ 4078.315824] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
>>> >> [ 4078.315824] CR2: ffffc900038d995e CR3: 00000000bb1ed000 CR4: 00000000000006e0
>>> >> [ 4078.315824] Stack:
>>> >> [ 4078.315824]  ffffffffa01ac797 ffff8800bb5bd480 ffff8800bb5bd4d0
>>> >> ffff8800bae87e48
>>> >> [ 4078.315824]  ffffffffa0073060 ffff88023466e800 0000000000000000
>>> >> 0000000000000fd8
>>> >> [ 4078.315824]  ffffffff00000001 ffff8800bacecc00 0000000000000fd8
>>> >> 0000000000008025
>>> >> [ 4078.315824] Call Trace:
>>> >> [ 4078.315824]  [<ffffffffa01ac797>] ? lttng_event_write+0x87/0xb0
>>> >> [lttng_ring_buffer_metadata_client]
>>> >> [ 4078.315824]  [<ffffffffa0073060>] lttng_metadata_output_channel+0xd0/0x120
>>> >> [lttng_tracer]
>>> >> [ 4078.315824]  [<ffffffffa00755f9>] lttng_metadata_ring_buffer_ioctl+0x79/0xd0
>>> >> [lttng_tracer]
>>> >> [ 4078.315824]  [<ffffffff8117ba10>] do_vfs_ioctl+0x2e0/0x4e0
>>> >> [ 4078.315824]  [<ffffffff812b35c7>] ? file_has_perm+0x87/0xa0
>>> >> [ 4078.315824]  [<ffffffff8117bc91>] SyS_ioctl+0x81/0xa0
>>> >> [ 4078.315824]  [<ffffffff810115d1>] ? syscall_trace_leave+0xd1/0xe0
>>> >> [ 4078.315824]  [<ffffffff818bbd37>] tracesys_phase2+0x84/0x89
>>> >> [ 4078.315824] Code: 5b 5d c3 66 0f 1f 44 00 00 e8 6b fc ff ff eb e1 90 90 90 90
>>> >> 90 90 90 90 90 0f 1f 44 00 00 48 89 f8 48 89 d1 48 c1 e9 03 83 e2 07 <f3> 48 a5
>>> >> 89 d1 f3 a4 c3 66 0f 1f 44 00 00 48 89 f8 48 89 d1 f3
>>> >> [ 4078.315824] RIP  [<ffffffff81316f12>] __memcpy+0x12/0x20
>>> >> [ 4078.315824]  RSP <ffff8800bae87da0>
>>> >> [ 4078.315824] CR2: ffffc900038d995e
>>> >> [ 4078.315824] ---[ end trace a05b652829ceda48 ]---
>>> >> [ 4078.433848] LTTng: block device enumeration is not supported by kernel
>>> >> 
>>> >> 
>>> >> --
>>> >> Mathieu Desnoyers
>>> >> EfficiOS Inc.
>>> >> http://www.efficios.com
>>> >> _______________________________________________
>>> >> lttng-dev mailing list
>>> >> lttng-dev@lists.lttng.org
>>> >> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
>>> > 
>>> > --
>>> > Mathieu Desnoyers
>>> > EfficiOS Inc.
>>> > http://www.efficios.com
>>> > 
>>> > _______________________________________________
>>> > lttng-dev mailing list
>>> > lttng-dev@lists.lttng.org
>>> > http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
>>> 
>>> --
>>> Mathieu Desnoyers
>>> EfficiOS Inc.
>> > http://www.efficios.com
> 
> --
> Mathieu Desnoyers
> EfficiOS Inc.
> http://www.efficios.com
> 
> _______________________________________________
> lttng-dev mailing list
> lttng-dev@lists.lttng.org
> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Jan Glauber]

On Thu, Jun 25, 2015 at 01:37:29PM +0000, Mathieu Desnoyers wrote:
> ----- On Jun 25, 2015, at 9:00 AM, Mathieu Desnoyers mathieu.desnoyers@efficios.com wrote:
> 
> > ----- On Jun 25, 2015, at 4:08 AM, Jan Glauber jan.glauber@gmail.com wrote:
> > 
> >> On Tue, Jun 23, 2015 at 09:04:18PM +0000, Mathieu Desnoyers wrote:
> >>> Nope, it wasn't it. metadata_written is always <= cache_alloc, so the
> >>> current upstream code looks correct.
> >>> 
> >>> I've just tried after changing the CPU configuration from "hypervisor
> >>> default" to "copy host cpu config" on my machine, and was then unable
> >>> to reproduce. I wonder if there is not an issue with __memcpy implementation
> >>> for specific x86_64 processors (e.g. reading too many bytes from the vmalloc'd
> >>> area).
> >>> 
> >>> Thoughts ?
> >> 
> >> Just speculation without further debugging data from the hypervisor setup
> >> where it fails...
> >> 
> >> From my understanding memcpy should work regardless of kmalloc or
> >> vmalloc.
> >> 
> >> Maybe the length parameter of the memcpy is wrong?
> >> With kmalloc and the 1:1 mapping this wont matter but if the memcpy
> >> crosses a page it might fault if the next page is not vmalloc'ed.
> >> 
> >> But the fault address ffffc900038d995e looks more like src is completely
> >> messed up.
> >> 
> >> What is the difference between the CPU configurations you tried?
> > 
> > Actually, I just narrowed it down to a missing mutex around the metadata
> > cache accesses. The updater can reallocate the memory, and the reader
> > (which outputs from the cache to a ring buffer) assumes that it does not
> > have to lock the metadata cache because it only reads its content.
> > Unfortunately, this does not take into account that the memory backing
> > the cache can be reallocated.
> > 
> > I'll prepare a fix.

Nice catch!

--Jan

[PATCH lttng-modules] Fix: Building the event list fails on fragmented memory

[Martin Leisener]

Hi Mathieu,

thanks for merging my arm patch! I found one more issue during my lttng-modules usages,
which can happen in low/fragmented memory situations. Please have a look, if you find this
patch useful/mergable. Again it is tested on x86 Ubuntu 12.04 LTS as well as my imx6 arm board.

Regards Martin


On a small arm imx6 solo with 256MB RAM it often happens that memory becomes fragmented rather
quickly, so that kmalloc will not be able to get enough consecutive pages (enocuntered for
example if you enable all kernel events: lttng enable-event -k syscall --all).

This patch switches the allocation to vmalloc. Tested for x86 on Ubuntu 12.04 Lts
and on imx6 solo 256MB RAM

If this patch is not applied, you can identify low and/or fragmented memory failures by
looking at the kernel ring buffer (please ignore DMA, it is due to some memory setup
misconfiguration, should read Normal):

...
[  321.993820] lttng-sessiond: page allocation failure: order:4, mode:0x1040d0
...
[  321.994711] lowmem_reserve[]: 0 0 0
[  321.994727] DMA: 801*4kB (UEMC) 424*8kB (EMC) 355*16kB (UEMC) 344*32kB (MC) 340*64kB (C) 8*128kB (C) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB 0*16384kB 0*32768kB = 46068kB

Signed-off-by: Martin Leisener <martin@leisener.de>
---
 lttng-events.c |   16 +++++++++++-----
 1 file changed, 11 insertions(+), 5 deletions(-)

diff --git a/lttng-events.c b/lttng-events.c
index 7eec04c..c861f71 100644
--- a/lttng-events.c
+++ b/lttng-events.c
@@ -39,6 +39,7 @@
 #include "wrapper/file.h"
 #include <linux/jhash.h>
 #include <linux/uaccess.h>
+#include <linux/vmalloc.h>
  #include "wrapper/uuid.h"
 #include "wrapper/vmalloc.h"	/* for wrapper_vmalloc_sync_all() */
@@ -132,10 +133,10 @@ struct lttng_session *lttng_session_create(void)
 			GFP_KERNEL);
 	if (!metadata_cache)
 		goto err_free_session;
-	metadata_cache->data = kzalloc(METADATA_CACHE_DEFAULT_SIZE,
-			GFP_KERNEL);
+	metadata_cache->data = vmalloc(METADATA_CACHE_DEFAULT_SIZE);
 	if (!metadata_cache->data)
 		goto err_free_cache;
+	memset(metadata_cache->data, 0, METADATA_CACHE_DEFAULT_SIZE);
 	metadata_cache->cache_alloc = METADATA_CACHE_DEFAULT_SIZE;
 	kref_init(&metadata_cache->refcount);
 	session->metadata_cache = metadata_cache;
@@ -162,7 +163,7 @@ void metadata_cache_destroy(struct kref *kref)
 {
 	struct lttng_metadata_cache *cache =
 		container_of(kref, struct lttng_metadata_cache, refcount);
-	kfree(cache->data);
+	vfree(cache->data);
 	kfree(cache);
 }
 @@ -1523,10 +1524,15 @@ int lttng_metadata_printf(struct lttng_session *session,
 		tmp_cache_alloc_size = max_t(unsigned int,
 				session->metadata_cache->cache_alloc + len,
 				session->metadata_cache->cache_alloc << 1);
-		tmp_cache_realloc = krealloc(session->metadata_cache->data,
-				tmp_cache_alloc_size, GFP_KERNEL);
+		tmp_cache_realloc = vmalloc(tmp_cache_alloc_size);
 		if (!tmp_cache_realloc)
 			goto err;
+		else if (session->metadata_cache->data) {
+			memset(tmp_cache_realloc, 0, tmp_cache_alloc_size);
+			memcpy(tmp_cache_realloc, session->metadata_cache->data, session->metadata_cache->cache_alloc);
+			vfree(session->metadata_cache->data);
+		}
+
 		session->metadata_cache->cache_alloc = tmp_cache_alloc_size;
 		session->metadata_cache->data = tmp_cache_realloc;
 	}
-- 
1.7.9.5