From mboxrd@z Thu Jan 1 00:00:00 1970 From: salman.rafiq@esk.fraunhofer.de (Salman Rafiq) Date: Wed, 18 Apr 2012 17:25:05 +0200 Subject: [lttng-dev] Babeltrace Buffer Warning In-Reply-To: <20120418135500.GA26947@Krystal> References: <20120413130156.GA10227@Krystal> <524C960C5DFC794E82BE548D825F05CF29EE58@EU-MBX-04.mgc.mentorg.com> <20120416135206.GA26549@Krystal> <524C960C5DFC794E82BE548D825F05CF29EF3E@EU-MBX-04.mgc.mentorg.com> <20120416143231.GA27877@Krystal> <20120418135500.GA26947@Krystal> Message-ID: Hello Mathieu, By looking into dmesg, I am not sure if it was page allocator bug or out-of-memory at that particular time. Does dmesg holds kernel messages from previous boot? Because the system was rebooted after the error occurred. Anyway I have attached the output of dmesg. Below is the rest of the information you asked for: Architecture: x86_64 Kernel Version: 3.0.0 Kernel .Config output also attached. Regards, S. -- Salman Rafiq Industrial Communication Fraunhofer-Einrichtung f?r Systeme der Kommunikationstechnik ESK Hansastra?e 32 | 80686 M?nchen Telefon, Fax: +49 89 547088-356 | +49 89 547088-66-356 E-Mail: salman.rafiq at esk.fraunhofer.de Internet: http://www.esk.fraunhofer.de http://www.facebook.com/FraunhoferESK http://www.twitter.com/FraunhoferESK -----Urspr?ngliche Nachricht----- Von: Mathieu Desnoyers [mailto:mathieu.desnoyers at efficios.com] Gesendet: Wednesday, April 18, 2012 3:55 PM An: Salman Rafiq Cc: Oestman, Fredrik; lttng-dev at lists.lttng.org Betreff: Re: AW: [lttng-dev] Babeltrace Buffer Warning * Salman Rafiq (salman.rafiq at esk.fraunhofer.de) wrote: > Hello All, > > Increasing the number of buffers and buffer size did helped indeed. Thanks to both for the advice. > > Another question is, what is the maximum --subbuf-size & --num-subbuf one can go? I guess it should depend upon your memory size? > > I am asking this because I had trouble last time, where my system crashed with some "general protection fault" while I had --subbuf-size of 2^29 . Attached are the syslog messages. Trying it on my x86_64 machine: lttng create lttng enable-channel test --subbuf-size 536870912 -k PERROR: ioctl kernel create channel: Invalid argument [in kernel_create_channel() at kernel.c:156] Error: Channel test: Kernel create channel failed (session auto-20120418-095035) Warning: Some command(s) went wrong dmesg tells me: [5408863.022967] lttng-sessiond: page allocation failure: order:10, mode:0xc0d0 [5408863.044885] Pid: 24301, comm: lttng-sessiond Tainted: G O 3.2.6-trace-test #129 [5408863.070423] Call Trace: [5408863.078337] [] warn_alloc_failed+0xf6/0x150 [5408863.096397] [] ? page_alloc_cpu_notify+0x60/0x60 [5408863.115795] [] __alloc_pages_nodemask+0x4d1/0x6d0 [5408863.135420] [] __get_free_pages+0x17/0x50 [5408863.152971] [] kmalloc_order_trace+0x3f/0x100 [5408863.171564] [] ? __kmalloc+0x1de/0x210 [5408863.188322] [] __kmalloc+0x1de/0x210 [5408863.204577] [] lib_ring_buffer_backend_create+0x1b6/0x500 [lttng_lib_ring_buffer] [5408863.232493] [] ? pcpu_next_pop+0x4b/0x70 [5408863.249776] [] lib_ring_buffer_create+0xad/0x2e0 [lttng_lib_ring_buffer] [5408863.275386] [] channel_backend_init+0x232/0x430 [lttng_lib_ring_buffer] [5408863.300738] [] channel_create+0x94/0x220 [lttng_lib_ring_buffer] [5408863.324265] [] ? kmem_cache_alloc_trace+0x133/0x150 [5408863.344374] [] _channel_create+0x33/0x40 [lttng_ring_buffer_client_discard] [5408863.370723] [] lttng_channel_create+0x14a/0x2c0 [lttng_tracer] [5408863.393678] [] lttng_abi_create_channel+0xcf/0x220 [lttng_tracer] [5408863.417413] [] lttng_session_ioctl+0x6a/0xa0 [lttng_tracer] [5408863.439589] [] do_vfs_ioctl+0x8f/0x500 [5408863.456299] [] ? fget_light+0x92/0x100 [5408863.473019] [] sys_ioctl+0x91/0xa0 [5408863.488699] [] system_call_fastpath+0x16/0x1b This is on a 3.2.6 kernel. Which architecture and kernel version are you using ? You might be hitting a kernel page allocator bug. Also, what is the content of your kernel .config ? Thanks, Mathieu > > > Regards, > S. > > -- > Salman Rafiq > Industrial Communication > Fraunhofer-Einrichtung f?r Systeme der Kommunikationstechnik ESK > > Hansastra?e 32 | 80686 M?nchen > Telefon, Fax: +49 89 547088-356 | +49 89 547088-66-356 > E-Mail: salman.rafiq at esk.fraunhofer.de > > Internet: > http://www.esk.fraunhofer.de > http://www.facebook.com/FraunhoferESK > http://www.twitter.com/FraunhoferESK > > > -----Urspr?ngliche Nachricht----- > Von: Mathieu Desnoyers [mailto:mathieu.desnoyers at efficios.com] > Gesendet: Monday, April 16, 2012 4:33 PM > An: Oestman, Fredrik > Cc: lttng-dev at lists.lttng.org; Salman Rafiq > Betreff: Re: [lttng-dev] Babeltrace Buffer Warning > > * Oestman, Fredrik (Fredrik_Oestman at mentor.com) wrote: > > Mathieu Desnoyers wrote: > > > The warning message is: > > > > > > "[warning] Tracer discarded 280625 events between > > > [1334315833.578351009] and [1334315833.578351380]. You should > > > consider increasing the buffer size." > > > > > > which states that the tracer did discard the events (not the > > > converter). > > > But maybe I'm missing your point. What would you recommend to make > > > this message clearer ? > > > > I actually had no recommendation or suggestion in mind. To me the message is clear. I just got the impression that the OP may have been confused in this respect for some reason. > > > > But since you ask, what about something along the lines of: > > > > "[warning] The tracer discarded 280625 events between > > [1334315833.578351009] and [1334315833.578351380]. You should > > consider making a new trace with larger buffers or with fewer event types enabled." > > Good idea. Fixed in commit: > > commit a0b34fbba498a8a447357adf5920ac2c8a22f026 > Author: Mathieu Desnoyers > Date: Mon Apr 16 10:33:55 2012 -0400 > > Clarify warning message for events discarded > > Reported-by: Fredrik Oestman > Signed-off-by: Mathieu Desnoyers > > Thanks! > > Mathieu > > > > > > > > Cheers, > > > > Fredrik ?stman > > > > -- > Mathieu Desnoyers > Operating System Efficiency R&D Consultant EfficiOS Inc. > http://www.efficios.com Content-Description: command_line.txt > Message from syslogd at oje at Apr 16 17:29:27 ... > kernel:[2777781.860828] general protection fault: 0000 [#1] SMP > > Message from syslogd at oje at Apr 16 17:29:27 ... > kernel:[2777781.864740] Stack: > > Message from syslogd at oje at Apr 16 17:29:27 ... > kernel:[2777781.864740] Call Trace: > > Message from syslogd at oje at Apr 16 17:29:27 ... > kernel:[2777781.864740] Code: 48 8b 7b 08 48 89 c5 48 8d 43 08 48 39 > c7 75 05 ff 43 04 eb 05 e8 10 e1 27 00 48 89 df 48 89 ee 5b 5b 5d e9 > b5 e6 27 00 90 eb 0c <8b> 50 10 39 56 10 7f 0c 48 8d 78 08 48 8b 07 48 > 85 c0 75 ec 48 Content-Description: syslogd.txt > Apr 16 17:29:27 oje kernel: [2777781.864435] CPU 4 Apr 16 17:29:27 oje > kernel: [2777781.864466] Modules linked in: lttng_probe_timer(O) > lttng_probe_statedump(O) lttng_probe_signal(O) lttng_probe_sched(O) > lttng_probe_kvm(O) lttng_probe_irq(O) lttng_probe_block(O) lttng_types(O) lttng_probe_lttng(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_kretprobes(O) lttng_kprobes(O) lttng_statedump(O) lttng_lib_ring_buffer(O) bnep rfcomm bluetooth rfkill crc16 parport_pc ppdev lp parport binfmt_misc fuse nfsd nfs lockd fscache auth_rpcgss nfs_acl sunrpc loop radeon joydev ttm drm_kms_helper drm edac_core shpchp nv_tco psmouse i2c_nforce2 i2c_algo_bit power_supply pci_hotplug pcspkr edac_mce_amd i2c_core evdev k10temp serio_raw ext3 jbd mbcache sg sr_mod sd_mod cdrom crc_t10dif usbhid hid ata_generic pata_amd ohci_hcd sata_nv libata ehci_hcd igb e1000 scsi_mod Apr 16 17:29:27 oje kernel: usbcore dca [last unloaded: lttng_kretprobes] Apr 16 17:29:27 oje kernel: [2777781.864740] > Apr 16 17:29:27 oje kernel: [2777781.864740] Pid: 5746, comm: lttng-sessiond Tainted: G W O 3.0.0opteron #4 Supermicro H8QM3/H8QM3 > Apr 16 17:29:27 oje kernel: [2777781.864740] RIP: > 0010:[] [] > notifier_chain_register+0x2/0x20 Apr 16 17:29:27 oje kernel: > [2777781.864740] RSP: 0018:ffff880077083bc0 EFLAGS: 00010282 Apr 16 > 17:29:27 oje kernel: [2777781.864740] RAX: a8c00e1ea8c0f2e6 RBX: > ffff8800bb113c50 RCX: 0000000000000010 Apr 16 17:29:27 oje kernel: > [2777781.864740] RDX: 0000000001082e40 RSI: ffff8800bb113c50 RDI: > ffff880030ffb858 Apr 16 17:29:27 oje kernel: [2777781.864740] RBP: > ffffffffa03b5270 R08: 0000000000000200 R09: ffffffff8167eff0 Apr 16 > 17:29:27 oje kernel: [2777781.864740] R10: 00000000000000c2 R11: > 00000000000000c2 R12: 00000000ffffffff Apr 16 17:29:27 oje kernel: > [2777781.864740] R13: ffff8801273fbc80 R14: 0000000010000000 R15: > 0000000000000010 Apr 16 17:29:27 oje kernel: [2777781.864740] FS: > 00007f7bd96a9700(0000) GS:ffff88012fc00000(0000) > knlGS:0000000000000000 Apr 16 17:29:27 oje kernel: [2777781.864740] > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Apr 16 17:29:27 oje > kernel: [2777781.864740] CR2: 00000000023332b0 CR3: 000000012d04b000 > CR4: 00000000000006e0 Apr 16 17:29:27 oje kernel: [2777781.864740] > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Apr > 16 17:29:27 oje kernel: [2777781.864740] DR3: 0000000000000000 DR6: > 00000000ffff0ff0 DR7: 0000000000000400 Apr 16 17:29:27 oje kernel: > [2777781.864740] Process lttng-sessiond (pid: 5746, threadinfo > ffff880077082000, task ffff8800772dc770) Apr 16 17:29:27 oje kernel: > [2777781.864740] ffffffff812c0ee0 ffff8801273fbc80 0000000010000000 > ffff8800bb113c10 Apr 16 17:29:27 oje kernel: [2777781.864740] > ffffffffa03a00e3 0000000000000246 0000001010000000 ffff8801273fbc80 > Apr 16 17:29:27 oje kernel: [2777781.864740] ffff8800bb113c00 > ffffffffa03b5270 ffffffffa0411188 ffff8800bb113c10 Apr 16 17:29:27 oje > kernel: [2777781.864740] [] ? > register_cpu_notifier+0x1c/0x2f Apr 16 17:29:27 oje kernel: > [2777781.864740] [] ? > channel_backend_init+0x189/0x2a0 [lttng_lib_ring_buffer] Apr 16 > 17:29:27 oje kernel: [2777781.864740] [] ? > channel_create+0x76/0x1ce [lttng_lib_ring_buffer] Apr 16 17:29:27 oje > kernel: [2777781.864740] [] ? > _channel_create+0x2b/0x30 [lttng_ring_buffer_client_discard] > Apr 16 17:29:27 oje kernel: [2777781.864740] [] ? > lttng_channel_create+0xeb/0x165 [lttng_tracer] Apr 16 17:29:27 oje > kernel: [2777781.864740] [] ? > lttng_abi_create_channel+0x122/0x1c5 [lttng_tracer] Apr 16 17:29:27 > oje kernel: [2777781.864740] [] ? > page_move_anon_rmap+0x1c/0x28 Apr 16 17:29:27 oje kernel: > [2777781.864740] [] ? lttng_session_ioctl+0x64/0x71 > [lttng_tracer] Apr 16 17:29:27 oje kernel: [2777781.864740] > [] ? do_vfs_ioctl+0x45c/0x49d Apr 16 17:29:27 oje > kernel: [2777781.864740] [] ? dput+0xd8/0xe4 Apr 16 > 17:29:27 oje kernel: [2777781.864740] [] ? > cpumask_next+0x16/0x18 Apr 16 17:29:27 oje kernel: [2777781.864740] > [] ? mnt_get_count+0x32/0x41 Apr 16 17:29:27 oje > kernel: [2777781.864740] [] ? sys_ioctl+0x4b/0x72 > Apr 16 17:29:27 oje kernel: [2777781.864740] [] ? > system_call_fastpath+0x16/0x1b Apr 16 17:29:27 oje kernel: > [2777781.864740] RSP Apr 16 17:29:27 oje kernel: > [2777782.091016] ---[ end trace fcc54233a1dc458e ]--- -- Mathieu Desnoyers Operating System Efficiency R&D Consultant EfficiOS Inc. http://www.efficios.com -------------- next part -------------- An embedded and charset-unspecified text was scrubbed... Name: dmessage.txt URL: -------------- next part -------------- An embedded and charset-unspecified text was scrubbed... Name: config_output.txt URL: