search

raspberrypi / firmware

This repository contains pre-compiled binaries of the current Raspberry Pi kernel and modules, userspace libraries, and bootloader/GPU firmware.
5.14k stars 1.68k forks source link

kworker task blocked - reading temperature? #192

Closed MilhouseVH closed 9 years ago

MilhouseVH commented 11 years ago

I left a headless 512MB Pi (16MB GPU, wired network on eth0) running with the latest firmware for several days, and it has just hung with the following backtrace:

Jun 29 19:42:57 raspberrypi upsmon[2208]: Poll UPS [ups@192.168.0.2] failed - Server disconnected
Jun 29 19:42:57 raspberrypi upsmon[2208]: Communications with UPS ups@192.168.0.2 lost
Jun 29 19:44:06 raspberrypi upsmon[2208]: UPS [ups@192.168.0.2]: connect failed: Connection failure: Connection timed out
Jun 29 19:45:14 raspberrypi upsmon[2208]: UPS [ups@192.168.0.2]: connect failed: Connection failure: Connection timed out
Jun 29 19:45:39 raspberrypi kernel: [745389.939467] INFO: task kworker/0:2:5386 blocked for more than 120 seconds.
Jun 29 19:45:39 raspberrypi kernel: [745389.939483] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun 29 19:45:39 raspberrypi kernel: [745389.939491] kworker/0:2     D c0398690     0  5386      2 0x00000000
Jun 29 19:45:39 raspberrypi kernel: [745389.939545] [<c0398690>] (__schedule+0x2c4/0x5b0) from [<c03973d0>] (schedule_timeout+0x158/0x1e0)
Jun 29 19:45:39 raspberrypi kernel: [745389.939703] [<c03973d0>] (schedule_timeout+0x158/0x1e0) from [<c03980c0>] (__down+0x88/0xc0)
Jun 29 19:45:39 raspberrypi kernel: [745389.939733] [<c03980c0>] (__down+0x88/0xc0) from [<c00400c0>] (down+0x60/0x64)
Jun 29 19:45:39 raspberrypi kernel: [745389.939764] [<c00400c0>] (down+0x60/0x64) from [<c001a678>] (bcm_mailbox_read+0x60/0x98)
Jun 29 19:45:39 raspberrypi kernel: [745389.939784] [<c001a678>] (bcm_mailbox_read+0x60/0x98) from [<c001a774>] (bcm_mailbox_property+0xc4/0x15c)
Jun 29 19:45:39 raspberrypi kernel: [745389.939811] [<c001a774>] (bcm_mailbox_property+0xc4/0x15c) from [<c02b1538>] (bcm2835_get_temp_or_max.isra.0+0x50/0xb8)
Jun 29 19:45:39 raspberrypi kernel: [745389.939831] [<c02b1538>] (bcm2835_get_temp_or_max.isra.0+0x50/0xb8) from [<c02b0520>] (thermal_zone_device_update+0x2c/0x240)
Jun 29 19:45:39 raspberrypi kernel: [745389.939850] [<c02b0520>] (thermal_zone_device_update+0x2c/0x240) from [<c0035010>] (process_one_work+0x150/0x40c)
Jun 29 19:45:39 raspberrypi kernel: [745389.939866] [<c0035010>] (process_one_work+0x150/0x40c) from [<c00355f0>] (worker_thread+0x150/0x498)
Jun 29 19:45:39 raspberrypi kernel: [745389.939887] [<c00355f0>] (worker_thread+0x150/0x498) from [<c003a7b4>] (kthread+0x88/0x94)
Jun 29 19:45:39 raspberrypi kernel: [745389.939910] [<c003a7b4>] (kthread+0x88/0x94) from [<c000e9fc>] (kernel_thread_exit+0x0/0x8)
Jun 29 19:46:22 raspberrypi upsmon[2208]: UPS [ups@192.168.0.2]: connect failed: Connection failure: Connection timed out
Jun 29 19:17:33 raspberrypi kernel: imklog 5.8.11, log source = /proc/kmsg started.

Current firmware:

pi@raspberrypi /var/log $ uname -a && vcgencmd version
Linux raspberrypi 3.6.11+ #474 PREEMPT Thu Jun 13 17:14:42 BST 2013 armv6l GNU/Linux
Jun 17 2013 20:43:10
Copyright (c) 2012 Broadcom
version d380dde43fe729f043befb5cf775f99e54586cde (clean) (release)

As with issue #132, I'm polling the temperature every 10 seconds, and the backtrace references bcm2835_get_temp so maybe there's still a problem there? However this doesn't appear to be a regression of #132 - running multiple concurrent processes reading the temperature do not provoke a backtrace.

A few minutes prior to this latest backtrace, the NUT client began reporting a communication problem with the network UPS which may be related (there is nothing wrong with the UPS, so it looks like an eth0 communication problem on the Pi side).

The Pi didn't actually crash, but it did lose all network access so had to be power cycled.

popcornmix commented 11 years ago

It could be that the GPU had crashed for other reasons (could there have been some glitch/surge that also killed the network), and the problem wasn't specific to reading the temperature.

If it happens again, check if any other communitcation with the GPU is possible. e.g. vcgenmd version hello_audio/hello_triangle/hello_video

MilhouseVH commented 11 years ago

If it happens again, check if any other communitcation with the GPU is possible.

Will do. I've now hooked it up to an HDMI monitor and added a USB keyboard, so next time it happens I should be able to confirm if the GPU has crashed or if it's just the network.

It's highly likely though that vcgencmd was not responding correctly shortly before the crash, here's the last output from the script that I received in my ssh session:

Time          ARM     Core     h264  Core Temp (Max)   Core  SDRam   IRQ/s      RX B/s      TX B/s   %user   %nice %system   %idle %iowait    %irq  %s/irq  %total  Memory Free/Used
========  =======  =======  =======  ===============  =====  =====  ======  ==========  ==========  ======  ======  ======  ======  ======  ======  ======  ======  ================
19:39:10  1000Mhz   500Mhz     0Mhz  54.07C (59.99C)  1.28V  1.23V     302         355       1,761    0.20    1.56    2.64   95.66    0.00    0.00    0.00    4.34  302,084 kB/39.3%
19:39:20  1000Mhz   500Mhz     0Mhz  55.15C (59.99C)  1.28V  1.23V     295         269       1,438    0.00    1.56    1.95   96.14    0.00    0.00    0.00    3.86  302,108 kB/39.3%
19:39:30  1000Mhz   500Mhz     0Mhz  54.61C (59.99C)  1.28V  1.23V     297         709       1,593    0.00    1.76    1.95   95.96    0.00    0.00    0.10    4.04  301,992 kB/39.3%
19:39:40  1000Mhz   500Mhz     0Mhz  55.15C (59.99C)  1.28V  1.23V     297         377       1,526    0.00    2.35    1.07   96.15    0.00    0.00    0.00    3.85  301,968 kB/39.3%
19:39:51  1000Mhz   500Mhz     0Mhz  54.07C (59.99C)  1.28V  1.23V     299         711       1,567    0.00    1.66    1.95   96.03    0.00    0.00    0.00    3.97  301,992 kB/39.3%
19:40:01  1000Mhz   500Mhz     0Mhz  55.15C (59.99C)  1.28V  1.23V     301         515       1,802    0.00    2.35    2.15   95.38    0.00    0.00    0.00    4.62  302,132 kB/39.3%
19:40:11  1000Mhz   500Mhz     0Mhz  54.61C (59.99C)  1.28V  1.23V     295         258       1,488    0.00    2.15    2.25   95.51    0.00    0.00    0.00    4.49  302,124 kB/39.3%
19:40:21   999Mhz   500Mhz     0Mhz  55.15C (59.99C)  1.28V  1.23V     297         807       1,487    0.00    1.66    2.25   96.09    0.00    0.00    0.00    3.91  302,100 kB/39.3%
19:40:32  1000Mhz   500Mhz     0Mhz  54.61C (59.99C)  1.28V  1.23V     297         238       1,538    0.00    2.24    1.95   95.92    0.00    0.00    0.00    4.08  302,024 kB/39.3%
19:40:42  1000Mhz   500Mhz     0Mhz  54.07C (59.99C)  1.28V  1.23V     326       1,235       6,836    0.00    6.45    2.25   91.19    0.00    0.00    0.00    8.81  301,984 kB/39.3%
19:40:52  1000Mhz   500Mhz     0Mhz  55.15C (59.99C)  1.28V  1.23V     296         728       1,510    0.00    2.05    1.56   95.90    0.00    0.00    0.10    4.10  301,984 kB/39.3%
19:41:02  1000Mhz   500Mhz     0Mhz  55.15C (59.99C)  1.28V  1.23V     302         384       2,659    0.00    2.15    1.66   95.67    0.00    0.00    0.00    4.33  302,100 kB/39.3%
19:41:13  1000Mhz   499Mhz     0Mhz  54.61C (59.99C)  1.28V  1.23V     297         716       1,566    0.00    2.63    1.95   95.49    0.00    0.00    0.00    4.51  302,124 kB/39.3%
19:41:23  1000Mhz   500Mhz     0Mhz  55.15C (59.99C)  1.28V  1.23V     299         287       1,583    0.00    1.85    1.56   96.04    0.00    0.00    0.10    3.96  302,068 kB/39.3%
19:41:33  1000Mhz   500Mhz     0Mhz  54.61C (59.99C)  1.28V  1.23V     295         216       1,466    0.00    1.95    1.76   96.08    0.00    0.00    0.00    3.92  302,108 kB/39.3%
19:41:43  1000Mhz   500Mhz     0Mhz  55.15C (59.99C)  1.28V  1.23V     300         994       1,673    0.00    2.05    1.95   95.89    0.00    0.00    0.00    4.11  302,100 kB/39.3%
19:41:54  1000Mhz   500Mhz     0Mhz  55.15C (59.99C)  1.28V  1.23V     298         319       2,025    0.00    3.12    1.66   94.95    0.00    0.00    0.00    5.05  302,100 kB/39.3%
19:42:04  1000Mhz   500Mhz     0Mhz  54.61C (59.99C)  1.28V  1.23V     298         380       1,681    0.00    1.47    2.74   95.73    0.00    0.00    0.00    4.27  302,000 kB/39.3%
19:42:14  1000Mhz   500Mhz     0Mhz  55.15C (59.99C)  1.28V  1.23V     299         658       1,486    0.00    1.76    1.76   96.06    0.00    0.00    0.00    3.94  302,108 kB/39.3%
19:42:24  1000Mhz   500Mhz     0Mhz  54.61C (59.99C)  1.28V  1.23V     296         289       1,513    0.00    2.34    1.66   96.04    0.00    0.00    0.10    3.96  302,100 kB/39.3%
19:42:34                                                                           324       1,571    0.00    2.05    1.56   95.76    0.10    0.00    0.00    4.24  302,124 kB/39.3%

The missing values in the final line correspond to vcgencmd calls (measure_clock arm/core/h264, measure_volts core/sdram_c). Temperature is read from /sys/class/thermal/thermal_zone0/temp. So although the network was still up, it looks like vcgencmd had already started to misbehave. After that final line, there was no further output from the script as the session disconnected at 19:42:42.

mtedaldi commented 10 years ago

Problem seems to persist with the version used in Raspbian: Linux Laserschrank 3.10.25+ #622 PREEMPT Fri Jan 3 18:41:00 GMT 2014 armv6l GNU/Linux Jan 6 2014 21:14:20 Copyright (c) 2012 Broadcom version b00bb3ae73bd2799df0e938b7a5f17f45303fb53 (clean) (release)

vcgencmd is called every 5 minutes three times by munin-node (temperature, volatges, freqencies)

It has run well for several days but has failed over the weekend leaving this in syslog:

Mar 21 20:29:00 Laserschrank kernel: [32042.965761] INFO: task kworker/0:0:10299 blocked for more than 120 seconds.
Mar 21 20:29:00 Laserschrank kernel: [32042.965819] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 21 20:29:00 Laserschrank kernel: [32042.965857] kworker/0:0     D c0400d1c     0 10299      2 0x00000000
Mar 21 20:29:00 Laserschrank kernel: [32042.965970] Workqueue: events od_dbs_timer
Mar 21 20:29:00 Laserschrank kernel: [32042.966107] [<c0400d1c>] (__schedule+0x278/0x558) from [<c03ffa98>] (schedule_timeout+0x170/
0x200)
Mar 21 20:29:00 Laserschrank kernel: [32042.966210] [<c03ffa98>] (schedule_timeout+0x170/0x200) from [<c0400798>] (__down+0x88/0xc0)
Mar 21 20:29:00 Laserschrank kernel: [32042.966327] [<c0400798>] (__down+0x88/0xc0) from [<c00418e4>] (down+0x60/0x64)
Mar 21 20:29:00 Laserschrank kernel: [32042.966427] [<c00418e4>] (down+0x60/0x64) from [<c001aa28>] (bcm_mailbox_read+0x60/0x98)
Mar 21 20:29:00 Laserschrank kernel: [32042.966511] [<c001aa28>] (bcm_mailbox_read+0x60/0x98) from [<c001ab24>] (bcm_mailbox_propert
y+0xc4/0x15c)
Mar 21 20:29:00 Laserschrank kernel: [32042.966620] [<c001ab24>] (bcm_mailbox_property+0xc4/0x15c) from [<c0307620>] (bcm2835_cpufre
q_driver_target+0x84/0x114)
Mar 21 20:29:00 Laserschrank kernel: [32042.966721] [<c0307620>] (bcm2835_cpufreq_driver_target+0x84/0x114) from [<c030353c>] (__cpu
freq_driver_target+0x50/0x74)
Mar 21 20:29:00 Laserschrank kernel: [32042.966814] [<c030353c>] (__cpufreq_driver_target+0x50/0x74) from [<c0306b70>] (dbs_check_cp
u+0xf4/0x144)
Mar 21 20:29:00 Laserschrank kernel: [32042.966909] [<c0306b70>] (dbs_check_cpu+0xf4/0x144) from [<c0305ff0>] (od_dbs_timer+0x60/0xe
c)
Mar 21 20:29:00 Laserschrank kernel: [32042.967011] [<c0305ff0>] (od_dbs_timer+0x60/0xec) from [<c0036ba4>] (process_one_work+0x10c/
0x360)
Mar 21 20:29:00 Laserschrank kernel: [32042.967105] [<c0036ba4>] (process_one_work+0x10c/0x360) from [<c0037258>] (worker_thread+0x1
38/0x3ac)
Mar 21 20:29:00 Laserschrank kernel: [32042.967194] [<c0037258>] (worker_thread+0x138/0x3ac) from [<c003ca34>] (kthread+0xa4/0xb0)
Mar 21 20:29:00 Laserschrank kernel: [32042.967295] [<c003ca34>] (kthread+0xa4/0xb0) from [<c000db58>] (ret_from_fork+0x14/0x3c)
Mar 21 20:29:00 Laserschrank kernel: [32042.967347] INFO: task vcgencmd:14633 blocked for more than 120 seconds.
Mar 21 20:29:00 Laserschrank kernel: [32042.967378] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Mar 21 20:29:00 Laserschrank kernel: [32042.967415] vcgencmd        D c0400d1c     0 14633      1 0x00000005
Mar 21 20:29:00 Laserschrank kernel: [32042.967545] [<c0400d1c>] (__schedule+0x278/0x558) from [<c03ffa98>] (schedule_timeout+0x170/
0x200)
Mar 21 20:29:00 Laserschrank kernel: [32042.967711] [<c03ffa98>] (schedule_timeout+0x170/0x200) from [<c0400798>] (__down+0x88/0xc0)
Mar 21 20:29:00 Laserschrank kernel: [32042.967872] [<c0400798>] (__down+0x88/0xc0) from [<c00418e4>] (down+0x60/0x64)
Mar 21 20:29:00 Laserschrank kernel: [32042.967988] [<c00418e4>] (down+0x60/0x64) from [<c0297d4c>] (vchiq_release+0xf4/0x2d4)
Mar 21 20:29:00 Laserschrank kernel: [32042.968093] [<c0297d4c>] (vchiq_release+0xf4/0x2d4) from [<c00d749c>] (__fput+0x8c/0x228)
Mar 21 20:29:00 Laserschrank kernel: [32042.968198] [<c00d749c>] (__fput+0x8c/0x228) from [<c0039bc8>] (task_work_run+0x84/0xb4)
Mar 21 20:29:00 Laserschrank kernel: [32042.968310] [<c0039bc8>] (task_work_run+0x84/0xb4) from [<c0023e28>] (do_exit+0x6b8/0x91c)
Mar 21 20:29:00 Laserschrank kernel: [32042.968410] [<c0023e28>] (do_exit+0x6b8/0x91c) from [<c00240f4>] (do_group_exit+0x3c/0xc4)
Mar 21 20:29:00 Laserschrank kernel: [32042.968526] [<c00240f4>] (do_group_exit+0x3c/0xc4) from [<c002e9ec>] (get_signal_to_deliver+
0x160/0x5ac)
Mar 21 20:29:00 Laserschrank kernel: [32042.968623] [<c002e9ec>] (get_signal_to_deliver+0x160/0x5ac) from [<c03fbd90>] (do_signal+0x
a8/0x3cc)
Mar 21 20:29:00 Laserschrank kernel: [32042.968731] [<c03fbd90>] (do_signal+0xa8/0x3cc) from [<c0010850>] (do_work_pending+0x9c/0xb0
)
Mar 21 20:29:00 Laserschrank kernel: [32042.968827] [<c0010850>] (do_work_pending+0x9c/0xb0) from [<c000db00>] (work_pending+0xc/0x2
0)

the vcgencmd processes were left as zombies on the system and the system load climbed to 700 over the weekend.

licaon-kter commented 10 years ago

sudo rpi-update and retest? and even if still present sudo BRANCH=next rpi-update and retest?

mtedaldi commented 10 years ago

@licaon-kter done just now. Mar 19 2014 23:24:26 Copyright (c) 2012 Broadcom version e071d425eca6ab200aefcf89056f3dcaf9510093 (tainted) (release)

Now let's wait and see. I have no way to force this error.

cleverca22 commented 10 years ago

i've found that the backtrace in the dmesg paste always happens when the VPU fails to respond to mailbox requests, usually when i crashed the VPU

the exact cause can vary wildly, makes me wonder if maybe popcornmix can expose a tool to make coredump of the VPU so we could submit the failure without needing to reproduce it?

ghollingworth commented 10 years ago

Not really, if there's no debugger attached then the processor is just going to go off and crash through memory doing 'bad stuff (tm)"

You can do this (basically what you do is read all of memory and write it to a file starting at 0 and finishing at 512MB). Popcornmix has a method of loading that into the debugger and at least understanding what the threads were doing the last time they were run, but doesn't actually give much in the way of useful information about the thread that actually crashed!

Gordon

cleverca22 commented 10 years ago

without the SP register, you cant get a decent backtrace?, and SP is only visible via jtag or a working VPU mailbox api?

any exception interrupts that could send a crashdump to the arm core?

mtedaldi commented 9 years ago

The hangs still occur. I'm not sure why. The Mailbox interrupt stops, kworker is endlessly waiting (Status D) and if I try to run "vcgenmod version" it also hangs and can't be terminated (except by rebooting the RasPi. System info: Linux Laserschrank 3.12.35+ #733 PREEMPT Tue Jan 6 21:03:44 GMT 2015 armv6l GNU/Linux Jan 6 2015 21:07:21 Copyright (c) 2012 Broadcom version 26e1e28d85832fedbbc72792f75071facbd89a48 (clean) (release)

popcornmix commented 9 years ago

@mtedaldi Do you have a procedure that reliably hangs? e.g. start from clean raspbian image, run a script and after certain period of time it usually hangs?

mtedaldi commented 9 years ago

It seems to be quite random. But it seems it happened more while I was monitoring frequency and core temperature every 5 minutes with munin. Than it happened sometimes after one day, sometimes after a week. Now, that I have stopped monitoring that, the intervals are longer.

I'm running that system headless (no display or keyboard/mouse).

I could try if I can force the hang by requesting temperature readings in a thight loop.

mtedaldi commented 9 years ago

@popcornmix I've tried to force it the whole day on friday. With no succes. Now it happened over the weekend (After it has not happened for more than 2 months, it has happened without any changes after x-mas). Since than, it happens every few days.

Her is the syslog-output from the last hang:

Jan 18 14:58:50 Laserschrank kernel: [270732.155456] INFO: task kworker/0:1:7581 blocked for more than 120 seconds.
Jan 18 14:58:50 Laserschrank kernel: [270732.155524]       Not tainted 3.12.35+ #733
Jan 18 14:58:50 Laserschrank kernel: [270732.155555] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 18 14:58:50 Laserschrank kernel: [270732.155589] kworker/0:1     D c044ab4c     0  7581      2 0x00000000
Jan 18 14:58:50 Laserschrank kernel: [270732.155706] Workqueue: events od_dbs_timer
Jan 18 14:58:50 Laserschrank kernel: [270732.155836] [<c044ab4c>] (__schedule+0x2a0/0x5ac) from [<c044903c>] (schedule_timeout+0x18c/0x21c)
Jan 18 14:58:50 Laserschrank kernel: [270732.155928] [<c044903c>] (schedule_timeout+0x18c/0x21c) from [<c044a574>] (__down+0x7c/0xb8)
Jan 18 14:58:50 Laserschrank kernel: [270732.156033] [<c044a574>] (__down+0x7c/0xb8) from [<c0040ea4>] (down+0x80/0x84)
Jan 18 14:58:50 Laserschrank kernel: [270732.156116] [<c0040ea4>] (down+0x80/0x84) from [<c001b4c0>] (dev_mbox_read+0x48/0x74)
Jan 18 14:58:50 Laserschrank kernel: [270732.156199] [<c001b4c0>] (dev_mbox_read+0x48/0x74) from [<c001b620>] (bcm_mailbox_property+0xa0/0x194)
Jan 18 14:58:50 Laserschrank kernel: [270732.156292] [<c001b620>] (bcm_mailbox_property+0xa0/0x194) from [<c0342d0c>] (bcm2835_cpufreq_driver_target+0x84/0x114)
Jan 18 14:58:50 Laserschrank kernel: [270732.156376] [<c0342d0c>] (bcm2835_cpufreq_driver_target+0x84/0x114) from [<c034210c>] (dbs_check_cpu+0xdc/0x110)
Jan 18 14:58:50 Laserschrank kernel: [270732.156470] [<c034210c>] (dbs_check_cpu+0xdc/0x110) from [<c03410ac>] (od_dbs_timer+0x60/0xec)
Jan 18 14:58:50 Laserschrank kernel: [270732.156568] [<c03410ac>] (od_dbs_timer+0x60/0xec) from [<c00354bc>] (process_one_work+0x118/0x378)
Jan 18 14:58:50 Laserschrank kernel: [270732.156654] [<c00354bc>] (process_one_work+0x118/0x378) from [<c00363fc>] (worker_thread+0x140/0x450)
Jan 18 14:58:50 Laserschrank kernel: [270732.156731] [<c00363fc>] (worker_thread+0x140/0x450) from [<c003c13c>] (kthread+0xa4/0xb0)
Jan 18 14:58:50 Laserschrank kernel: [270732.156821] [<c003c13c>] (kthread+0xa4/0xb0) from [<c000df58>] (ret_from_fork+0x14/0x3c)
popcornmix commented 9 years ago

@mtedaldi It's more likely that the gpu has crashed for other reasons and this just happens to be the first command that notices. Can you run subsequent commands (e.g. through ssh)? If so then do other commnds that use gpu fail (e.g. vcgencmd version?) Were you using any gpu features? (e.g. 3d, video, camera) Are you overclocking? Perhaps try disabling that.

mtedaldi commented 9 years ago

@popcornmix I'm not using the GPU (knowingly). There is nothing attached except the network-cable (and some i2c stuff). Yes, I can connect to the device by ssh after the mailbox interrupt stops working. I see slightly longer delays. Calling vcgenmod version blocks (Uninterruptable). I'm not overclocking. I'm underclocking (and have installed some heatsinks, keeping the CPU Temperature below 40°C most of the time. Most of the time, the CPU runs at 200MHz, every 5 minutes going to 700MHz (because munin monitoring stuff).

popcornmix commented 9 years ago

After the hang, can you report output of:

sudo vcdbg log msg
sudo vcdbg reloc
sudo vcdbg malloc

to see if there are any complaints from gpu.

mtedaldi commented 9 years ago

So finally, my Raspi decided to kill the mailbox interrupt again (gain, while I was not around, so I only got to investigate it after 3 days)

tedaldi@Laserschrank ~ $ uname -a && vcgencmd version
Linux Laserschrank 3.12.35+ #733 PREEMPT Tue Jan 6 21:03:44 GMT 2015 armv6l GNU/Linux
Jan  6 2015 21:07:21
Copyright (c) 2012 Broadcom
version 26e1e28d85832fedbbc72792f75071facbd89a48 (clean) (release)

@popcornmix the results of the commands:

tedaldi@Laserschrank ~ $ sudo vcdbg log msg
Unable to determine the value of __LOG_START
Unable to read logging_header from 0x00000000
tedaldi@Laserschrank ~ $ sudo vcdbg reloc

Relocatable heap version 4 found at 0x1f000000
total space allocated is 10M, with 10M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

free list at 0x1f086820
9.5M free memory in 1 free block(s)
largest free block is 9.5M bytes

[   1] 0x1f000000: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x1f000020, d0ruAl) 'audioplus_tmp_buf'
[   2] 0x1f004020: used 522K (refcount 1 lock count 8, size   530432, align 4096, data 0x1f005000, d3rual) 'ARM FB'
0x1f086820: free 9.5M
small allocs not requested
tedaldi@Laserschrank ~ $ sudo vcdbg malloc
Pool 0x9fb2d9f8 (1fa7cbc8)
Malloc pool size=4.8M (pool=0x1fb2d9f8-0x1fffff2c)
0x1fb2da20 = malloc(4.0K) [call from 0x1fa51856]
0x1fb2ea40 = malloc(8)    [call from 0x1fa4508a]
0x1fb2ea80 = malloc(7.1K) [dma_transfer_xfers]
0x1fb30720 = malloc(8.0K) [call from 0x1fa64818]
0x1fb32740 = malloc(100)  [call from 0x1fa64834]
0x1fb327e0 = malloc(32K)  [call from 0x1fa2dcca]
0x1fb3a800 = malloc(512)  [call from 0x1fa41f9e]
0x1fb3aa20 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3ab60 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3aca0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3ade0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3af20 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3b060 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3b1a0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3b2e0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3b420 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3b560 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3b6a0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3b7e0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3b920 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3ba60 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3bba0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3bce0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3be20 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3bf60 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3c0a0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3c1e0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3c320 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3c460 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3c5a0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3c6e0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3c820 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3c960 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3caa0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3cbe0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3cd20 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3ce60 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3cfa0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3d0e0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3d220 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3d360 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3d4a0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3d5e0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3d720 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3d860 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3d9a0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3dae0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3dc20 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3dd60 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3dea0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3dfe0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3e120 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3e260 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3e3a0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3e4e0 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3e620 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3e760 = malloc(272)  [call from 0x1fa2ddb8]
0x1fb3e8a0 = malloc(512)  [call from 0x1fa09c82]
0x1fb3eac0 = malloc(16K)  [call from 0x1fa09cb4]
0x1fb42ae0 = malloc(4.0K) [call from 0x1fa09d10]
0x1fb43b00 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43b60 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43bc0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43c20 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43c80 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43ce0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43d40 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43da0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43e00 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43e60 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43ec0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43f20 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43f80 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb43fe0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44040 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb440a0 = malloc(7.0K) [Gencmd service state]
0x1fb45ce0 = malloc(180)  [vcos_cmd_entries]
0x1fb45dc0 = malloc(4.0K) [reaper]
0x1fb46de0 = malloc(8)    [call from 0x1fa143f2]
0x1fb46e20 = malloc(4.0K) [powerman]
0x1fb47e40 = malloc(3.0K) [call from 0x1fa1e29a]
0x1fb48a60 = malloc(11K)  [call from 0x1fa1e2d0]
0x1fb4b700 = malloc(11K)  [call from 0x1fa1e304]
0x1fb4e3a0 = malloc(3.9K) [call from 0x1fa1e33a]
0x1fb4f380 = malloc(1.1K) [call from 0x1fa5edbe]
0x1fb4f800 = malloc(4.0K) [call from 0x1fa39cc0]
0x1fb50820 = malloc(4.0K) [call from 0x1fa39cec]
0x1fb51840 = malloc(16K)  [call from 0x1fa10620]
0x1fb55860 = malloc(16K)  [mbox_read]
0x1fb59880 = malloc(4.0K) [display_update]
0x1fb5a8a0 = malloc(4.0K) [temp_check]
0x1fb5b8c0 = malloc(16K)  [vchiq dma_xfer]
0x1fb5f980 = malloc(16K)  [vchiq dma_xfer]
0x1fb63a40 = malloc(16K)  [vchiq dma_xfer]
0x1fb67b00 = malloc(16K)  [vchiq dma_xfer]
0x1fb6bbc0 = malloc(8.0K) [VCHIQ-0]
0x1fb6dbe0 = malloc(8.0K) [VCHIQr-0]
0x1fb6fc00 = malloc(8.0K) [VCHIQs-0]
0x1fb71c20 = malloc(36)   [vchiq_shim]
0x1fb71c80 = malloc(256)  [vchiu_queue_init]
0x1fb71da0 = malloc(476)  [VCHIQ service]
0x1fb71fa0 = malloc(36)   [vchiq_shim]
0x1fb72000 = malloc(256)  [vchiu_queue_init]
0x1fb72120 = malloc(476)  [VCHIQ service]
0x1fb72320 = malloc(36)   [vchiq_shim]
0x1fb72380 = malloc(256)  [vchiu_queue_init]
0x1fb724a0 = malloc(476)  [VCHIQ service]
0x1fb726a0 = malloc(2.0K) [call from 0x1fa64818]
0x1fb72ea0 = malloc(100)  [call from 0x1fa64834]
0x1fb72f40 = malloc(4.0K) [GCMD_V]
0x1fb73f60 = malloc(1.3K) [CEA modes table]
0x1fb744a0 = malloc(1.7K) [DMT modes table]
0x1fb74ba0 = malloc(4.0K) [call from 0x1fa6045a]
0x1fb75bc0 = malloc(36)   [vchiq_shim]
0x1fb75c20 = malloc(256)  [vchiu_queue_init]
0x1fb75d40 = malloc(476)  [VCHIQ service]
0x1fb75f40 = malloc(36)   [vchiq_shim]
0x1fb75fa0 = malloc(256)  [vchiu_queue_init]
0x1fb760c0 = malloc(476)  [VCHIQ service]
0x1fb762c0 = malloc(36)   [vchiq_shim]
0x1fb76320 = malloc(256)  [vchiu_queue_init]
0x1fb76440 = malloc(476)  [VCHIQ service]
0x1fb76640 = malloc(4.0K) [call from 0x1fa604d6]
0x1fb77660 = malloc(36)   [vchiq_shim]
0x1fb776c0 = malloc(256)  [vchiu_queue_init]
0x1fb777e0 = malloc(476)  [VCHIQ service]
0x1fb779e0 = malloc(36)   [vchiq_shim]
0x1fb77a40 = malloc(256)  [vchiu_queue_init]
0x1fb77b60 = malloc(476)  [VCHIQ service]
0x1fb77d60 = malloc(36)   [vchiq_shim]
0x1fb77dc0 = malloc(256)  [vchiu_queue_init]
0x1fb77ee0 = malloc(476)  [VCHIQ service]
0x1fb780e0 = malloc(4.0K) []
0x1fb79100 = malloc(36)   [vchiq_shim]
0x1fb79160 = malloc(256)  [vchiu_queue_init]
0x1fb79280 = malloc(476)  [VCHIQ service]
0x1fb79480 = malloc(36)   [vchiq_shim]
0x1fb794e0 = malloc(256)  [vchiu_queue_init]
0x1fb79600 = malloc(476)  [VCHIQ service]
0x1fb79800 = malloc(36)   [vchiq_shim]
0x1fb79860 = malloc(256)  [vchiu_queue_init]
0x1fb79980 = malloc(476)  [VCHIQ service]
0x1fb79b80 = malloc(4.0K) []
0x1fb7aba0 = malloc(36)   [vchiq_shim]
0x1fb7ac00 = malloc(256)  [vchiu_queue_init]
0x1fb7ad20 = malloc(476)  [VCHIQ service]
0x1fb7af20 = malloc(36)   [vchiq_shim]
0x1fb7af80 = malloc(256)  [vchiu_queue_init]
0x1fb7b0a0 = malloc(476)  [VCHIQ service]
0x1fb7b2a0 = malloc(36)   [vchiq_shim]
0x1fb7b300 = malloc(256)  [vchiu_queue_init]
0x1fb7b420 = malloc(476)  [VCHIQ service]
0x1fb7b620 = malloc(36)   [vchiq_shim]
0x1fb7b680 = malloc(256)  [vchiu_queue_init]
0x1fb7b7a0 = malloc(476)  [VCHIQ service]
0x1fb7b9a0 = malloc(36)   [vchiq_shim]
0x1fb7ba00 = malloc(256)  [vchiu_queue_init]
0x1fb7bb20 = malloc(476)  [VCHIQ service]
0x1fb7bd20 = malloc(36)   [vchiq_shim]
0x1fb7bd80 = malloc(256)  [vchiu_queue_init]
0x1fb7bea0 = malloc(476)  [VCHIQ service]
0x1fb7c0a0 = malloc(36)   [vchiq_shim]
0x1fb7c100 = malloc(256)  [vchiu_queue_init]
0x1fb7c220 = malloc(476)  [VCHIQ service]
0x1fb7c420 = malloc(36)   [vchiq_shim]
0x1fb7c480 = malloc(256)  [vchiu_queue_init]
0x1fb7c5a0 = malloc(476)  [VCHIQ service]
0x1fb7c7a0 = malloc(36)   [vchiq_shim]
0x1fb7c800 = malloc(256)  [vchiu_queue_init]
0x1fb7c920 = malloc(476)  [VCHIQ service]
0x1fb7cb20 = malloc(36)   [vchiq_shim]
0x1fb7cb80 = malloc(256)  [vchiu_queue_init]
0x1fb7cca0 = malloc(476)  [VCHIQ service]
0x1fb7cea0 = malloc(36)   [vchiq_shim]
0x1fb7cf00 = malloc(256)  [vchiu_queue_init]
0x1fb7d020 = malloc(476)  [VCHIQ service]
0x1fb7d220 = malloc(476)  [VCHIQ service]
0x1fb7d420 = malloc(4.0K) [vc watchdog]
0x1fb7e430 = hole(4.5M)
Malloced:323K Remaining:4.5M
tedaldi@Laserschrank ~ $
mtedaldi commented 9 years ago

@popcornmix And another one (after everything is updated, even the firmware) 

tedaldi@Laserschrank ~ $ uname -a && vcgencmd version
Linux Laserschrank 3.18.6+ #753 PREEMPT Sun Feb 8 14:47:22 GMT 2015 armv6l GNU/Linux
Feb  7 2015 19:32:11
Copyright (c) 2012 Broadcom
version e3cfc1e5001c71261c4d79e852723910772ffba9 (clean) (release)
tedaldi@Laserschrank ~ $ sudo vcdbg log msg
Unable to determine the value of __LOG_START
Unable to read logging_header from 0x00000000
tedaldi@Laserschrank ~ $ sudo vcdbg reloc

Relocatable heap version 4 found at 0x1f000000
total space allocated is 10M, with 10M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

free list at 0x1f979780
9.5M free memory in 1 free block(s)
largest free block is 9.5M bytes

0x1f000000: free 9.5M
[   2] 0x1f9797a0: used 522K (refcount 1 lock count 8, size   530432, align 4096, data 0x1f97a000, d3rual) 'ARM FB'
[   1] 0x1f9fbfc0: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x1f9fbfe0, d0ruAl) 'audioplus_tmp_buf'
small allocs not requested
tedaldi@Laserschrank ~ $ sudo vcdbg malloc
Pool 0x9fb2e758 (1fa7d928)
Malloc pool size=4.8M (pool=0x1fb2e758-0x1fffff2c)
0x1fb2e780 = malloc(4.0K) [call from 0x1fa524de]
0x1fb2f7a0 = malloc(8)    [call from 0x1fa45bb8]
0x1fb2f7e0 = malloc(7.1K) [dma_transfer_xfers]
0x1fb31480 = malloc(8.0K) [call from 0x1fa65538]
0x1fb334a0 = malloc(100)  [call from 0x1fa65554]
0x1fb33540 = malloc(32K)  [call from 0x1fa2e1a6]
0x1fb3b560 = malloc(512)  [call from 0x1fa424f6]
0x1fb3b780 = malloc(272)  [call from 0x1fa2e294]
0x1fb3b8c0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3ba00 = malloc(272)  [call from 0x1fa2e294]
0x1fb3bb40 = malloc(272)  [call from 0x1fa2e294]
0x1fb3bc80 = malloc(272)  [call from 0x1fa2e294]
0x1fb3bdc0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3bf00 = malloc(272)  [call from 0x1fa2e294]
0x1fb3c040 = malloc(272)  [call from 0x1fa2e294]
0x1fb3c180 = malloc(272)  [call from 0x1fa2e294]
0x1fb3c2c0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3c400 = malloc(272)  [call from 0x1fa2e294]
0x1fb3c540 = malloc(272)  [call from 0x1fa2e294]
0x1fb3c680 = malloc(272)  [call from 0x1fa2e294]
0x1fb3c7c0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3c900 = malloc(272)  [call from 0x1fa2e294]
0x1fb3ca40 = malloc(272)  [call from 0x1fa2e294]
0x1fb3cb80 = malloc(272)  [call from 0x1fa2e294]
0x1fb3ccc0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3ce00 = malloc(272)  [call from 0x1fa2e294]
0x1fb3cf40 = malloc(272)  [call from 0x1fa2e294]
0x1fb3d080 = malloc(272)  [call from 0x1fa2e294]
0x1fb3d1c0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3d300 = malloc(272)  [call from 0x1fa2e294]
0x1fb3d440 = malloc(272)  [call from 0x1fa2e294]
0x1fb3d580 = malloc(272)  [call from 0x1fa2e294]
0x1fb3d6c0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3d800 = malloc(272)  [call from 0x1fa2e294]
0x1fb3d940 = malloc(272)  [call from 0x1fa2e294]
0x1fb3da80 = malloc(272)  [call from 0x1fa2e294]
0x1fb3dbc0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3dd00 = malloc(272)  [call from 0x1fa2e294]
0x1fb3de40 = malloc(272)  [call from 0x1fa2e294]
0x1fb3df80 = malloc(272)  [call from 0x1fa2e294]
0x1fb3e0c0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3e200 = malloc(272)  [call from 0x1fa2e294]
0x1fb3e340 = malloc(272)  [call from 0x1fa2e294]
0x1fb3e480 = malloc(272)  [call from 0x1fa2e294]
0x1fb3e5c0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3e700 = malloc(272)  [call from 0x1fa2e294]
0x1fb3e840 = malloc(272)  [call from 0x1fa2e294]
0x1fb3e980 = malloc(272)  [call from 0x1fa2e294]
0x1fb3eac0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3ec00 = malloc(272)  [call from 0x1fa2e294]
0x1fb3ed40 = malloc(272)  [call from 0x1fa2e294]
0x1fb3ee80 = malloc(272)  [call from 0x1fa2e294]
0x1fb3efc0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3f100 = malloc(272)  [call from 0x1fa2e294]
0x1fb3f240 = malloc(272)  [call from 0x1fa2e294]
0x1fb3f380 = malloc(272)  [call from 0x1fa2e294]
0x1fb3f4c0 = malloc(272)  [call from 0x1fa2e294]
0x1fb3f600 = malloc(512)  [call from 0x1fa09c82]
0x1fb3f820 = malloc(16K)  [call from 0x1fa09cb4]
0x1fb43840 = malloc(4.0K) [call from 0x1fa09d10]
0x1fb44860 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb448c0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44920 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44980 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb449e0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44a40 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44aa0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44b00 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44b60 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44bc0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44c20 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44c80 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44ce0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44d40 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44da0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1fb44e00 = malloc(7.0K) [Gencmd service state]
0x1fb46a40 = malloc(180)  [vcos_cmd_entries]
0x1fb46b20 = malloc(4.0K) [reaper]
0x1fb47b40 = malloc(8)    [call from 0x1fa14486]
0x1fb47b80 = malloc(4.0K) [powerman]
0x1fb48ba0 = malloc(3.0K) [call from 0x1fa1e4f2]
0x1fb497c0 = malloc(11K)  [call from 0x1fa1e528]
0x1fb4c460 = malloc(11K)  [call from 0x1fa1e55c]
0x1fb4f100 = malloc(3.9K) [call from 0x1fa1e592]
0x1fb500e0 = malloc(1.1K) [call from 0x1fa5fade]
0x1fb50560 = malloc(4.0K) [call from 0x1fa3a218]
0x1fb51580 = malloc(4.0K) [call from 0x1fa3a244]
0x1fb525a0 = malloc(16K)  [call from 0x1fa10594]
0x1fb565c0 = malloc(16K)  [mbox_read]
0x1fb5a5e0 = malloc(4.0K) [display_update]
0x1fb5b600 = malloc(4.0K) [temp_check]
0x1fb5c620 = malloc(16K)  [vchiq dma_xfer]
0x1fb606e0 = malloc(16K)  [vchiq dma_xfer]
0x1fb647a0 = malloc(16K)  [vchiq dma_xfer]
0x1fb68860 = malloc(16K)  [vchiq dma_xfer]
0x1fb6c920 = malloc(8.0K) [VCHIQ-0]
0x1fb6e940 = malloc(8.0K) [VCHIQr-0]
0x1fb70960 = malloc(8.0K) [VCHIQs-0]
0x1fb72980 = malloc(36)   [vchiq_shim]
0x1fb729e0 = malloc(256)  [vchiu_queue_init]
0x1fb72b00 = malloc(476)  [VCHIQ service]
0x1fb72d00 = malloc(36)   [vchiq_shim]
0x1fb72d60 = malloc(256)  [vchiu_queue_init]
0x1fb72e80 = malloc(476)  [VCHIQ service]
0x1fb73080 = malloc(36)   [vchiq_shim]
0x1fb730e0 = malloc(256)  [vchiu_queue_init]
0x1fb73200 = malloc(476)  [VCHIQ service]
0x1fb73400 = malloc(2.0K) [call from 0x1fa65538]
0x1fb73c00 = malloc(100)  [call from 0x1fa65554]
0x1fb73ca0 = malloc(4.0K) [GCMD_V]
0x1fb74cc0 = malloc(1.3K) [CEA modes table]
0x1fb75200 = malloc(1.7K) [DMT modes table]
0x1fb75900 = malloc(4.0K) [call from 0x1fa6117a]
0x1fb76920 = malloc(36)   [vchiq_shim]
0x1fb76980 = malloc(256)  [vchiu_queue_init]
0x1fb76aa0 = malloc(476)  [VCHIQ service]
0x1fb76ca0 = malloc(36)   [vchiq_shim]
0x1fb76d00 = malloc(256)  [vchiu_queue_init]
0x1fb76e20 = malloc(476)  [VCHIQ service]
0x1fb77020 = malloc(36)   [vchiq_shim]
0x1fb77080 = malloc(256)  [vchiu_queue_init]
0x1fb771a0 = malloc(476)  [VCHIQ service]
0x1fb773a0 = malloc(4.0K) [call from 0x1fa611f6]
0x1fb783c0 = malloc(36)   [vchiq_shim]
0x1fb78420 = malloc(256)  [vchiu_queue_init]
0x1fb78540 = malloc(476)  [VCHIQ service]
0x1fb78740 = malloc(36)   [vchiq_shim]
0x1fb787a0 = malloc(256)  [vchiu_queue_init]
0x1fb788c0 = malloc(476)  [VCHIQ service]
0x1fb78ac0 = malloc(36)   [vchiq_shim]
0x1fb78b20 = malloc(256)  [vchiu_queue_init]
0x1fb78c40 = malloc(476)  [VCHIQ service]
0x1fb78e40 = malloc(4.0K) []
0x1fb79e60 = malloc(36)   [vchiq_shim]
0x1fb79ec0 = malloc(256)  [vchiu_queue_init]
0x1fb79fe0 = malloc(476)  [VCHIQ service]
0x1fb7a1e0 = malloc(36)   [vchiq_shim]
0x1fb7a240 = malloc(256)  [vchiu_queue_init]
0x1fb7a360 = malloc(476)  [VCHIQ service]
0x1fb7a560 = malloc(36)   [vchiq_shim]
0x1fb7a5c0 = malloc(256)  [vchiu_queue_init]
0x1fb7a6e0 = malloc(476)  [VCHIQ service]
0x1fb7a8e0 = malloc(4.0K) []
0x1fb7b900 = malloc(36)   [vchiq_shim]
0x1fb7b960 = malloc(256)  [vchiu_queue_init]
0x1fb7ba80 = malloc(476)  [VCHIQ service]
0x1fb7bc80 = malloc(36)   [vchiq_shim]
0x1fb7bce0 = malloc(256)  [vchiu_queue_init]
0x1fb7be00 = malloc(476)  [VCHIQ service]
0x1fb7c000 = malloc(36)   [vchiq_shim]
0x1fb7c060 = malloc(256)  [vchiu_queue_init]
0x1fb7c180 = malloc(476)  [VCHIQ service]
0x1fb7c380 = malloc(36)   [vchiq_shim]
0x1fb7c3e0 = malloc(256)  [vchiu_queue_init]
0x1fb7c500 = malloc(476)  [VCHIQ service]
0x1fb7c700 = malloc(36)   [vchiq_shim]
0x1fb7c760 = malloc(256)  [vchiu_queue_init]
0x1fb7c880 = malloc(476)  [VCHIQ service]
0x1fb7ca80 = malloc(36)   [vchiq_shim]
0x1fb7cae0 = malloc(256)  [vchiu_queue_init]
0x1fb7cc00 = malloc(476)  [VCHIQ service]
0x1fb7ce00 = malloc(36)   [vchiq_shim]
0x1fb7ce60 = malloc(256)  [vchiu_queue_init]
0x1fb7cf80 = malloc(476)  [VCHIQ service]
0x1fb7d180 = malloc(36)   [vchiq_shim]
0x1fb7d1e0 = malloc(256)  [vchiu_queue_init]
0x1fb7d300 = malloc(476)  [VCHIQ service]
0x1fb7d500 = malloc(36)   [vchiq_shim]
0x1fb7d560 = malloc(256)  [vchiu_queue_init]
0x1fb7d680 = malloc(476)  [VCHIQ service]
0x1fb7d880 = malloc(36)   [vchiq_shim]
0x1fb7d8e0 = malloc(256)  [vchiu_queue_init]
0x1fb7da00 = malloc(476)  [VCHIQ service]
0x1fb7dc00 = malloc(36)   [vchiq_shim]
0x1fb7dc60 = malloc(256)  [vchiu_queue_init]
0x1fb7dd80 = malloc(476)  [VCHIQ service]
0x1fb7df80 = malloc(476)  [VCHIQ service]
0x1fb7e180 = malloc(4.0K) [vc watchdog]
0x1fb7f190 = hole(4.5M)
Malloced:323K Remaining:4.5M
popcornmix commented 9 years ago

@mtedaldi I assume you are running with gpu_mem=16? Is it anydifferent with, say, gpu_mem=64? In that case sudo vcdbg log msg should work, which could give some info.

mtedaldi commented 9 years ago

@popcornmix it took some time after that change, but now it happened again:

tedaldi@Laserschrank ~ $ uptime
 08:39:03 up 20 days, 17:40,  1 user,  load average: 1.09, 1.13, 1.10
tedaldi@Laserschrank ~ $ uname -a
Linux Laserschrank 3.18.7+ #755 PREEMPT Thu Feb 12 17:14:31 GMT 2015 armv6l GNU/Linux
tedaldi@Laserschrank ~ $ vcgencmd version
Feb 14 2015 22:23:03
Copyright (c) 2012 Broadcom
version 7789db485409720b0e523a3d6b86b12ed56fd152 (clean) (release)
tedaldi@Laserschrank ~ $ sudo vcdbg log msg
[sudo] password for tedaldi:
003109.600: HDMI:EDID error reading EDID block 0 attempt 0
003110.863: HDMI:EDID error reading EDID block 0 attempt 1
003112.122: HDMI:EDID error reading EDID block 0 attempt 2
003113.380: HDMI:EDID error reading EDID block 0 attempt 3
003114.639: HDMI:EDID error reading EDID block 0 attempt 4
003115.897: HDMI:EDID error reading EDID block 0 attempt 5
003117.156: HDMI:EDID error reading EDID block 0 attempt 6
003118.415: HDMI:EDID error reading EDID block 0 attempt 7
003119.674: HDMI:EDID error reading EDID block 0 attempt 8
003120.932: HDMI:EDID error reading EDID block 0 attempt 9
003121.954: HDMI:EDID giving up on reading EDID block 0
003125.059: HDMI:Setting property pixel encoding to Default
003125.085: HDMI:Setting property pixel clock type to PAL
003125.108: HDMI:Setting property content type flag to No data
003125.133: HDMI:Setting property fuzzy format match to enabled
003130.727: gpioman: gpioman_get_pin_num: pin LEDS_RUNNING not defined
003130.750: gpioman: gpioman_get_pin_num: pin LEDS_NAND_ACTIVITY not defined
003130.771: gpioman: gpioman_get_pin_num: pin LEDS_USB_ACTIVITY not defined
003130.792: gpioman: gpioman_get_pin_num: pin LEDS_FATAL_ERROR not defined
003130.813: gpioman: gpioman_get_pin_num: pin LEDS_APP_OK not defined
003130.835: gpioman: gpioman_get_pin_num: pin LEDS_APP_FAILED not defined
003130.855: gpioman: gpioman_get_pin_num: pin LEDS_HDCP_AUTH not defined
003130.877: gpioman: gpioman_get_pin_num: pin LEDS_HDCP_UNAUTH not defined
003130.898: gpioman: gpioman_get_pin_num: pin LEDS_HDMI_ON not defined
003130.920: gpioman: gpioman_get_pin_num: pin LEDS_DVI_ON not defined
003130.942: gpioman: gpioman_get_pin_num: pin LEDS_HDMI_HPD_UP not defined
003130.963: gpioman: gpioman_get_pin_num: pin LEDS_REMOTE_CONTROL not defined
003130.983: gpioman: gpioman_get_pin_num: pin LEDS_ARM_CONTROLLED not defined
003136.159: hdmi: HDMI:>>>>>>>>>>>>>Rx sensed, reading EDID<<<<<<<<<<<<<
003136.666: hdmi: HDMI:EDID error reading EDID block 0 attempt 0
003137.933: hdmi: HDMI:EDID error reading EDID block 0 attempt 1
003139.196: hdmi: HDMI:EDID error reading EDID block 0 attempt 2
003140.458: hdmi: HDMI:EDID error reading EDID block 0 attempt 3
003141.721: hdmi: HDMI:EDID error reading EDID block 0 attempt 4
003142.983: hdmi: HDMI:EDID error reading EDID block 0 attempt 5
003144.246: hdmi: HDMI:EDID error reading EDID block 0 attempt 6
003145.508: hdmi: HDMI:EDID error reading EDID block 0 attempt 7
003146.770: hdmi: HDMI:EDID error reading EDID block 0 attempt 8
003148.032: hdmi: HDMI:EDID error reading EDID block 0 attempt 9
003149.058: hdmi: HDMI:EDID giving up on reading EDID block 0
003149.105: hdmi: HDMI: No lookup table for resolution group 0
003149.123: hdmi: HDMI: hotplug attached with DVI support
003149.193: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
003149.680: hdmi: HDMI:EDID error reading EDID block 0 attempt 0
003150.943: hdmi: HDMI:EDID error reading EDID block 0 attempt 1
003152.206: hdmi: HDMI:EDID error reading EDID block 0 attempt 2
003153.470: hdmi: HDMI:EDID error reading EDID block 0 attempt 3
003154.734: hdmi: HDMI:EDID error reading EDID block 0 attempt 4
003155.998: hdmi: HDMI:EDID error reading EDID block 0 attempt 5
003157.261: hdmi: HDMI:EDID error reading EDID block 0 attempt 6
003158.526: hdmi: HDMI:EDID error reading EDID block 0 attempt 7
003159.789: hdmi: HDMI:EDID error reading EDID block 0 attempt 8
003161.052: hdmi: HDMI:EDID error reading EDID block 0 attempt 9
003162.079: hdmi: HDMI:EDID giving up on reading EDID block 0
003164.789: hdmi: HDMI: power_on to DMT mode VGA@60
003167.007: hdmi: HDMI: Action callback added to queue to happen at frame 0
003183.509: *** Restart logging

003184.876: Read command line from file 'cmdline.txt'
dwc_otg.lpm_enable=0 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p6 rootfstype=ext4 elevator=deadline rootwait

003186.422: Loading 'kernel.img' from SD card
003459.566: Kernel trailer DTOK property says yes
003461.098: Loading 'bcm2708-rpi-b.dtb' from SD card
003466.215: dtparam: i2c_arm=on
003468.235: dtparam: i2c0=on
003470.106: dtparam: arm_freq=700000000
003470.638: Unknown param 'arm_freq' - ignored
003484.741: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
007248.618: vchiq_core: vchiq_init_state: slot_zero = 0x5b800000, is_master = 1
007252.367: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
007254.983: cma: cma_hwm is zero - disabling cma service
007256.406: gpioman: gpioman_get_pin_num: pin LEDS_RUNNING not defined
007256.430: gpioman: gpioman_get_pin_num: pin LEDS_NAND_ACTIVITY not defined
007256.450: gpioman: gpioman_get_pin_num: pin LEDS_USB_ACTIVITY not defined
007256.470: gpioman: gpioman_get_pin_num: pin LEDS_FATAL_ERROR not defined
007256.492: gpioman: gpioman_get_pin_num: pin LEDS_APP_OK not defined
007256.514: gpioman: gpioman_get_pin_num: pin LEDS_APP_FAILED not defined
007256.535: gpioman: gpioman_get_pin_num: pin LEDS_HDCP_AUTH not defined
007256.557: gpioman: gpioman_get_pin_num: pin LEDS_HDCP_UNAUTH not defined
007256.578: gpioman: gpioman_get_pin_num: pin LEDS_HDMI_ON not defined
007256.600: gpioman: gpioman_get_pin_num: pin LEDS_DVI_ON not defined
007256.622: gpioman: gpioman_get_pin_num: pin LEDS_HDMI_HPD_UP not defined
007256.642: gpioman: gpioman_get_pin_num: pin LEDS_REMOTE_CONTROL not defined
007256.663: gpioman: gpioman_get_pin_num: pin LEDS_ARM_CONTROLLED not defined
007257.009: TV service:host side not connected, dropping notification 0x00000002, 0x00000002, 0x00000004
tedaldi@Laserschrank ~ $ sudo vcdbg reloc

Relocatable heap version 4 found at 0x1c000000
total space allocated is 44M, with 44M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

free list at 0x1eb78520
43M free memory in 1 free block(s)
largest free block is 43M bytes

0x1c000000: free 43M
[   4] 0x1eb78540: used  576 (refcount 1 lock count 0, size      512, align    4, data 0x1eb78560, d0rual) 'ILCS VC buffer pool'
[   3] 0x1eb78780: used 522K (refcount 1 lock count 8, size   530432, align 4096, data 0x1eb79000, d3rual) 'ARM FB'
[   2] 0x1ebfafa0: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x1ebfafc0, d0ruAl) 'audioplus_tmp_buf'
[   1] 0x1ebfefe0: used 4.0K (refcount 1 lock count 0, size        0, align 4096, data 0x1ebff000, d1rual) 'camera fast alloc arena'
small allocs not requested
tedaldi@Laserschrank ~ $ sudo vcdbg malloc
Pool 0x9f2d4818 (1ee5e00c)
Malloc pool size=13M (pool=0x1f2d4818-0x1ff7ff2c)
0x1f2d4840 = malloc(128K) [call from 0x1ed9e552]
0x1f2f4860 = malloc(24)   [call from 0x1ed4fbf4]
0x1f2f5000 = malloc(138K) [call from 0x1ec882f8]
0x1f3181c0 = malloc(512)  [v3d_gfxh16_thre]
0x1f3183e0 = malloc(7.1K) [dma_transfer_xfers]
0x1f31a080 = malloc(7.0K) [Gencmd service state]
0x1f31bcc0 = malloc(180)  [vcos_cmd_entries]
0x1f31bda0 = malloc(4.0K) [reaper]
0x1f31cdc0 = malloc(8.0K) [call from 0x1ee0faa8]
0x1f31ede0 = malloc(100)  [call from 0x1ee0fac4]
0x1f31ee80 = malloc(32K)  [call from 0x1eccdc2e]
0x1f326ea0 = malloc(512)  [call from 0x1ed33770]
0x1f3270c0 = malloc(272)  [call from 0x1eccdd1c]
0x1f327200 = malloc(272)  [call from 0x1eccdd1c]
0x1f327340 = malloc(272)  [call from 0x1eccdd1c]
0x1f327480 = malloc(272)  [call from 0x1eccdd1c]
0x1f3275c0 = malloc(272)  [call from 0x1eccdd1c]
0x1f327700 = malloc(272)  [call from 0x1eccdd1c]
0x1f327840 = malloc(272)  [call from 0x1eccdd1c]
0x1f327980 = malloc(272)  [call from 0x1eccdd1c]
0x1f327ac0 = malloc(272)  [call from 0x1eccdd1c]
0x1f327c00 = malloc(272)  [call from 0x1eccdd1c]
0x1f327d40 = malloc(272)  [call from 0x1eccdd1c]
0x1f327e80 = malloc(272)  [call from 0x1eccdd1c]
0x1f327fc0 = malloc(272)  [call from 0x1eccdd1c]
0x1f328100 = malloc(272)  [call from 0x1eccdd1c]
0x1f328240 = malloc(272)  [call from 0x1eccdd1c]
0x1f328380 = malloc(272)  [call from 0x1eccdd1c]
0x1f3284c0 = malloc(272)  [call from 0x1eccdd1c]
0x1f328600 = malloc(272)  [call from 0x1eccdd1c]
0x1f328740 = malloc(272)  [call from 0x1eccdd1c]
0x1f328880 = malloc(272)  [call from 0x1eccdd1c]
0x1f3289c0 = malloc(272)  [call from 0x1eccdd1c]
0x1f328b00 = malloc(272)  [call from 0x1eccdd1c]
0x1f328c40 = malloc(272)  [call from 0x1eccdd1c]
0x1f328d80 = malloc(272)  [call from 0x1eccdd1c]
0x1f328ec0 = malloc(272)  [call from 0x1eccdd1c]
0x1f329000 = malloc(272)  [call from 0x1eccdd1c]
0x1f329140 = malloc(272)  [call from 0x1eccdd1c]
0x1f329280 = malloc(272)  [call from 0x1eccdd1c]
0x1f3293c0 = malloc(272)  [call from 0x1eccdd1c]
0x1f329500 = malloc(272)  [call from 0x1eccdd1c]
0x1f329640 = malloc(272)  [call from 0x1eccdd1c]
0x1f329780 = malloc(272)  [call from 0x1eccdd1c]
0x1f3298c0 = malloc(272)  [call from 0x1eccdd1c]
0x1f329a00 = malloc(272)  [call from 0x1eccdd1c]
0x1f329b40 = malloc(272)  [call from 0x1eccdd1c]
0x1f329c80 = malloc(272)  [call from 0x1eccdd1c]
0x1f329dc0 = malloc(272)  [call from 0x1eccdd1c]
0x1f329f00 = malloc(272)  [call from 0x1eccdd1c]
0x1f32a040 = malloc(272)  [call from 0x1eccdd1c]
0x1f32a180 = malloc(272)  [call from 0x1eccdd1c]
0x1f32a2c0 = malloc(272)  [call from 0x1eccdd1c]
0x1f32a400 = malloc(272)  [call from 0x1eccdd1c]
0x1f32a540 = malloc(272)  [call from 0x1eccdd1c]
0x1f32a680 = malloc(272)  [call from 0x1eccdd1c]
0x1f32a7c0 = malloc(272)  [call from 0x1eccdd1c]
0x1f32a900 = malloc(272)  [call from 0x1eccdd1c]
0x1f32aa40 = malloc(272)  [call from 0x1eccdd1c]
0x1f32ab80 = malloc(272)  [call from 0x1eccdd1c]
0x1f32acc0 = malloc(272)  [call from 0x1eccdd1c]
0x1f32ae00 = malloc(272)  [call from 0x1eccdd1c]
0x1f32af40 = malloc(512)  [call from 0x1ec5dbd8]
0x1f32b160 = malloc(16K)  [call from 0x1ec5dc0a]
0x1f32f180 = malloc(4.0K) [call from 0x1ec5dc66]
0x1f3301a0 = malloc(4.0K) [call from 0x1ed189f0]
0x1f3311c0 = malloc(4.0K) [call from 0x1ed18a1c]
0x1f3321e0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f332240 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f3322a0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f332300 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f332360 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f3323c0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f332420 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f332480 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f3324e0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f332540 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f3325a0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f332600 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f332660 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f3326c0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f332720 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f332780 = malloc(8)    [call from 0x1ec7ab8e]
0x1f3327c0 = malloc(4.0K) [powerman]
0x1f3337e0 = malloc(3.0K) [call from 0x1eca896a]
0x1f334400 = malloc(356K) [call from 0x1eca89a0]
0x1f38d420 = malloc(356K) [call from 0x1eca89da]
0x1f3e6440 = malloc(66K)  [call from 0x1eca8a1c]
0x1f3f6c20 = malloc(1.1K) [call from 0x1edcf572]
0x1f3f70a0 = malloc(16K)  [call from 0x1ec7456a]
0x1f3fb0c0 = malloc(16K)  [mbox_read]
0x1f3ff0e0 = malloc(4.0K) [display_update]
0x1f400100 = malloc(4.0K) [temp_check]
0x1f401120 = malloc(16K)  [vchiq dma_xfer]
0x1f4051e0 = malloc(16K)  [vchiq dma_xfer]
0x1f4092a0 = malloc(16K)  [vchiq dma_xfer]
0x1f40d360 = malloc(16K)  [vchiq dma_xfer]
0x1f411420 = malloc(8.0K) [VCHIQ-0]
0x1f413440 = malloc(8.0K) [VCHIQr-0]
0x1f415460 = malloc(8.0K) [VCHIQs-0]
0x1f417480 = malloc(56)   [imageconv stats]
0x1f4174e0 = malloc(36)   [vchiq_shim]
0x1f417540 = malloc(256)  [vchiu_queue_init]
0x1f417660 = malloc(476)  [VCHIQ service]
0x1f417860 = malloc(36)   [vchiq_shim]
0x1f4178c0 = malloc(256)  [vchiu_queue_init]
0x1f4179e0 = malloc(476)  [VCHIQ service]
0x1f417be0 = malloc(36)   [vchiq_shim]
0x1f417c40 = malloc(256)  [vchiu_queue_init]
0x1f417d60 = malloc(476)  [VCHIQ service]
0x1f417f60 = malloc(2.0K) [call from 0x1ee0faa8]
0x1f418760 = malloc(100)  [call from 0x1ee0fac4]
0x1f418800 = malloc(4.0K) [GCMD_V]
0x1f419820 = malloc(2.0K) [HAUDVCHI]
0x1f41a040 = malloc(36)   [vchiq_shim]
0x1f41a0a0 = malloc(256)  [vchiu_queue_init]
0x1f41a1c0 = malloc(476)  [VCHIQ service]
0x1f41a3c0 = malloc(21K)  [ILCS State]
0x1f41f680 = malloc(256)  [vchiu_queue_init]
0x1f41f7a0 = malloc(476)  [VCHIQ service]
0x1f41f9a0 = malloc(52)   [ILCS_VC_COMMON]
0x1f41fa00 = malloc(4.0K) [ILCS_VC]
0x1f420a20 = malloc(3.0K) [call from 0x1edd877c]
0x1f421640 = malloc(36)   [vchiq_shim]
0x1f4216a0 = malloc(256)  [vchiu_queue_init]
0x1f4217c0 = malloc(476)  [VCHIQ service]
0x1f4219c0 = malloc(36)   [vchiq_shim]
0x1f421a20 = malloc(256)  [vchiu_queue_init]
0x1f421b40 = malloc(476)  [VCHIQ service]
0x1f421d40 = malloc(36)   [vchiq_shim]
0x1f421da0 = malloc(256)  [vchiu_queue_init]
0x1f421ec0 = malloc(476)  [VCHIQ service]
0x1f4220c0 = malloc(3.0K) [call from 0x1edd87f2]
0x1f422ce0 = malloc(36)   [vchiq_shim]
0x1f422d40 = malloc(256)  [vchiu_queue_init]
0x1f422e60 = malloc(476)  [VCHIQ service]
0x1f423060 = malloc(36)   [vchiq_shim]
0x1f4230c0 = malloc(256)  [vchiu_queue_init]
0x1f4231e0 = malloc(476)  [VCHIQ service]
0x1f4233e0 = malloc(36)   [vchiq_shim]
0x1f423440 = malloc(256)  [vchiu_queue_init]
0x1f423560 = malloc(476)  [VCHIQ service]
0x1f423760 = malloc(60)   [call from 0x1ed48750]
0x1f4237c0 = malloc(16K)  [vchiu_queue_init]
0x1f4277e0 = malloc(476)  [VCHIQ service]
0x1f4279e0 = malloc(60)   [call from 0x1ed48750]
0x1f427a40 = malloc(16K)  [vchiu_queue_init]
0x1f42ba60 = malloc(476)  [VCHIQ service]
0x1f42bc60 = malloc(60)   [call from 0x1ed48750]
0x1f42bcc0 = malloc(16K)  [vchiu_queue_init]
0x1f42fce0 = malloc(476)  [VCHIQ service]
0x1f42fee0 = malloc(476)  [VCHIQ service]
0x1f4300e0 = malloc(320K) [KHRN_S]
0x1f480100 = malloc(36)   [vchiq_shim]
0x1f480160 = malloc(256)  [vchiu_queue_init]
0x1f480280 = malloc(476)  [VCHIQ service]
0x1f480480 = malloc(4.0K) [HREQ task]
0x1f4814a0 = malloc(4.6K) [call from 0x1edd88b4]
0x1f482720 = malloc(4.0K) [FILESERV]
0x1f483740 = malloc(36)   [vchiq_shim]
0x1f4837a0 = malloc(256)  [vchiu_queue_init]
0x1f4838c0 = malloc(476)  [VCHIQ service]
0x1f483ac0 = malloc(608)  [Shared Memory Service]
0x1f483d40 = malloc(4.0K) [sm_thread]
0x1f484d60 = malloc(36)   [vchiq_shim]
0x1f484dc0 = malloc(256)  [vchiu_queue_init]
0x1f484ee0 = malloc(476)  [VCHIQ service]
0x1f4850e0 = malloc(488)  [Shared Memory Cache Test]
0x1f485300 = malloc(4.0K) [smct_thread]
0x1f486320 = malloc(36)   [vchiq_shim]
0x1f486380 = malloc(256)  [vchiu_queue_init]
0x1f4864a0 = malloc(476)  [VCHIQ service]
0x1f4866a0 = malloc(1.3K) [CEA modes table]
0x1f486be0 = malloc(1.7K) [DMT modes table]
0x1f4872e0 = malloc(4.0K) [call from 0x1edd9686]
0x1f488300 = malloc(36)   [vchiq_shim]
0x1f488360 = malloc(256)  [vchiu_queue_init]
0x1f488480 = malloc(476)  [VCHIQ service]
0x1f488680 = malloc(36)   [vchiq_shim]
0x1f4886e0 = malloc(256)  [vchiu_queue_init]
0x1f488800 = malloc(476)  [VCHIQ service]
0x1f488a00 = malloc(36)   [vchiq_shim]
0x1f488a60 = malloc(256)  [vchiu_queue_init]
0x1f488b80 = malloc(476)  [VCHIQ service]
0x1f488d80 = malloc(4.0K) [call from 0x1edd9702]
0x1f489da0 = malloc(36)   [vchiq_shim]
0x1f489e00 = malloc(256)  [vchiu_queue_init]
0x1f489f20 = malloc(476)  [VCHIQ service]
0x1f48a120 = malloc(36)   [vchiq_shim]
0x1f48a180 = malloc(256)  [vchiu_queue_init]
0x1f48a2a0 = malloc(476)  [VCHIQ service]
0x1f48a4a0 = malloc(36)   [vchiq_shim]
0x1f48a500 = malloc(256)  [vchiu_queue_init]
0x1f48a620 = malloc(476)  [VCHIQ service]
0x1f48a820 = malloc(4.0K) []
0x1f48b840 = malloc(36)   [vchiq_shim]
0x1f48b8a0 = malloc(256)  [vchiu_queue_init]
0x1f48b9c0 = malloc(476)  [VCHIQ service]
0x1f48bbc0 = malloc(36)   [vchiq_shim]
0x1f48bc20 = malloc(256)  [vchiu_queue_init]
0x1f48bd40 = malloc(476)  [VCHIQ service]
0x1f48bf40 = malloc(36)   [vchiq_shim]
0x1f48bfa0 = malloc(256)  [vchiu_queue_init]
0x1f48c0c0 = malloc(476)  [VCHIQ service]
0x1f48c2c0 = malloc(4.0K) []
0x1f48d2e0 = malloc(36)   [vchiq_shim]
0x1f48d340 = malloc(256)  [vchiu_queue_init]
0x1f48d460 = malloc(476)  [VCHIQ service]
0x1f48d660 = malloc(36)   [vchiq_shim]
0x1f48d6c0 = malloc(256)  [vchiu_queue_init]
0x1f48d7e0 = malloc(476)  [VCHIQ service]
0x1f48d9e0 = malloc(36)   [vchiq_shim]
0x1f48da40 = malloc(256)  [vchiu_queue_init]
0x1f48db60 = malloc(476)  [VCHIQ service]
0x1f48dd60 = malloc(36)   [vchiq_shim]
0x1f48ddc0 = malloc(256)  [vchiu_queue_init]
0x1f48dee0 = malloc(476)  [VCHIQ service]
0x1f48e0e0 = malloc(36)   [vchiq_shim]
0x1f48e140 = malloc(256)  [vchiu_queue_init]
0x1f48e260 = malloc(476)  [VCHIQ service]
0x1f48e460 = malloc(36)   [vchiq_shim]
0x1f48e4c0 = malloc(256)  [vchiu_queue_init]
0x1f48e5e0 = malloc(476)  [VCHIQ service]
0x1f48e7e0 = malloc(36)   [vchiq_shim]
0x1f48e840 = malloc(256)  [vchiu_queue_init]
0x1f48e960 = malloc(476)  [VCHIQ service]
0x1f48eb60 = malloc(36)   [vchiq_shim]
0x1f48ebc0 = malloc(256)  [vchiu_queue_init]
0x1f48ece0 = malloc(476)  [VCHIQ service]
0x1f48eee0 = malloc(36)   [vchiq_shim]
0x1f48ef40 = malloc(256)  [vchiu_queue_init]
0x1f48f060 = malloc(476)  [VCHIQ service]
0x1f48f260 = malloc(36)   [vchiq_shim]
0x1f48f2c0 = malloc(256)  [vchiu_queue_init]
0x1f48f3e0 = malloc(476)  [VCHIQ service]
0x1f48f5e0 = malloc(36)   [vchiq_shim]
0x1f48f640 = malloc(256)  [vchiu_queue_init]
0x1f48f760 = malloc(476)  [VCHIQ service]
0x1f48f960 = malloc(476)  [VCHIQ service]
0x1f48fb60 = malloc(476)  [VCHIQ service]
0x1f48fd60 = malloc(476)  [VCHIQ service]
0x1f48ff60 = malloc(476)  [VCHIQ service]
0x1f490160 = malloc(476)  [VCHIQ service]
0x1f490360 = malloc(476)  [VCHIQ service]
0x1f490560 = malloc(476)  [VCHIQ service]
0x1f490760 = malloc(476)  [VCHIQ service]
0x1f490960 = malloc(476)  [VCHIQ service]
0x1f490b60 = malloc(476)  [VCHIQ service]
0x1f490d60 = malloc(4.3K) [mmal debug log]
0x1f491ea0 = malloc(16K)  [mmal_host_log]
0x1f495ee0 = malloc(512)  [vchiu_queue_init]
0x1f496100 = malloc(476)  [VCHIQ service]
0x1f496300 = malloc(40)   [call from 0x1ed5965a]
0x1f496360 = malloc(40)   [call from 0x1ed5965a]
0x1f4963c0 = malloc(40)   [call from 0x1ed5965a]
0x1f496420 = malloc(40)   [call from 0x1ed5965a]
0x1f496480 = malloc(40)   [call from 0x1ed5965a]
0x1f4964e0 = malloc(40)   [call from 0x1ed5965a]
0x1f496540 = malloc(40)   [call from 0x1ed5965a]
0x1f4965a0 = malloc(40)   [call from 0x1ed5965a]
0x1f496600 = malloc(40)   [call from 0x1ed5965a]
0x1f496660 = malloc(40)   [call from 0x1ed5965a]
0x1f4966c0 = malloc(40)   [call from 0x1ed5965a]
0x1f496720 = malloc(40)   [call from 0x1ed5965a]
0x1f496780 = malloc(40)   [call from 0x1ed5965a]
0x1f4967e0 = malloc(40)   [call from 0x1ed5965a]
0x1f496840 = malloc(40)   [call from 0x1ed5965a]
0x1f4968a0 = malloc(40)   [call from 0x1ed5965a]
0x1f496900 = malloc(40)   [call from 0x1ed5965a]
0x1f496960 = malloc(40)   [call from 0x1ed5965a]
0x1f4969c0 = malloc(40)   [call from 0x1ed5965a]
0x1f496a20 = malloc(40)   [call from 0x1ed5965a]
0x1f496a80 = malloc(40)   [call from 0x1ed5965a]
0x1f496ae0 = malloc(256)  [mmal msg queue mem]
0x1f496c00 = malloc(4.0K) [mmal msg queue ]
0x1f497c20 = malloc(4.0K) [mmal msg queue ]
0x1f498c40 = malloc(4.0K) [mmal worker]
0x1f499c60 = malloc(476)  [VCHIQ service]
0x1f499e60 = malloc(4.0K) [vc watchdog]
0x1f49ae70 = hole(11M)
Malloced:1.8M Remaining:11M
tedaldi@Laserschrank ~ $
popcornmix commented 9 years ago

Does removing the underclock help? You can read freq/temp without using gencmd.

cat /sys/class/thermal/thermal_zone0/temp
cat /sys/devices/system/cpu/cpu0/cpufreq/scaling_cur_freq

If you use those, does the problem still occur?

mtedaldi commented 9 years ago

@popcornmix I have removed the underclocking some time ago. I just set "arm_freq_min=200" and I'm using the "ondemand" governor.

Even using cat on the /sys/ interface blocked when trying to read in such a case. So in the background this driver seems to rely on the same infrastructure as the gencmd.

mtedaldi commented 9 years ago

@popcornmix Now THAT's interesting. I've removed the "arm_freq_min=200" statement from the config.txt (commented it out) and rebooted. Now, the mailbox-irq is silent (0.00 interrupts/s) but everything works nicely!

So it seems that the frequency scaling somehow led to this situation. So, until the next crash (which probably won't occur) the problem seems to be solved. Now it would just be interesting, why frequency scaling has led to such problems.

popcornmix commented 9 years ago

For completeness could you try arm_freq=710 (i.e. a very small overclock). I'd like to know if any frequency scaling causes the hang, or if it's only underclocking that has the problem. Underclocking is pretty rarely done, so that code path may be less well tested.

citiq commented 9 years ago

Having a very recent kernel and firmware on a headless RPi, the GPU hangs after a day. Java was playing an audio (using libasound) to audio jack at that time. Since then a short sound pattern (might be the last buffer contents) is repeated on the audio output. 

pi@rpi:~$ uname -a
Linux rpi 3.18.9-v6+ #3 PREEMPT Thu Mar 19 09:58:16 UTC 2015 armv6l GNU/Linux
pi@rpi:~$ cat /proc/cpuinfo |grep -i bcm -A1
Hardware    : BCM2708
Revision    : 0010

vcgencmd version and bcmstat after reboot (not executable when broken): 

pi@rpi:~$ sudo /opt/vc/bin/vcgencmd version
Mar 16 2015 19:38:52 
Copyright (c) 2012 Broadcom
version 51ab816b505d1b745130562908d866915c836056 (clean) (release)
pi@rpi:~$ sudo ./bcmstat.sh
  Config: v0.2.1, args "", priority lowest (+19)
     CPU: 1 x ARMv6 core available, using ondemand governor
  Memory: 512MB (split 480MB ARM, 32MB GPU)
HW Block: |   ARM   |  Core  |  H264  |    SDRAM    |
Min Freq: |  700MHz | 250MHz |   0MHz |    400MHz   |
Max Freq: |  700MHz | 250MHz | 250MHz |    400MHz   |
Voltages: |         0, 1.2000V        |  0, 1.2000V |
   Other: temp_limit=85
Firmware: Mar 16 2015 19:38:52, version 51ab816b505d1b745130562908d866915c836056 (clean) (release)
  Codecs: H264 MJPG
  Booted: Tue Mar 24 07:54:11 2015

Time         ARM    Core    H264 Core Temp (Max)  IRQ/s     RX B/s     TX B/s
======== ======= ======= ======= =============== ====== ========== ==========
09:54:24  700Mhz  250Mhz    0Mhz 37.39C (37.39C)  3,240      1,219      4,707
09:54:27  700Mhz  250Mhz    0Mhz 37.39C (37.39C)  3,231        143      1,009^C
Peak Values: IRQ: 3240, RX: 1219, TX: 4707

Configuration files:

pi@rpi:~$ cat /boot/config.txt 
[pi1]
# customer kernel
kernel=kernel_custom.img

[pi2]
# customer kernel
kernel=kernel_custom7.img

[all]
# uncomment if you get no picture on HDMI for a default "safe" mode
#hdmi_safe=1

# uncomment this if your display has a black border of unused pixels visible
# and your display can output without overscan
#disable_overscan=1

# uncomment the following to adjust overscan. Use positive numbers if console
# goes off screen, and negative if there is too much border
#overscan_left=16
#overscan_right=16
#overscan_top=16
#overscan_bottom=16

# uncomment to force a console size. By default it will be display's size minus
# overscan.
#framebuffer_width=1280
#framebuffer_height=720

# uncomment if hdmi display is not detected and composite is being output
#hdmi_force_hotplug=1

# uncomment to force a specific HDMI mode (this will force VGA)
#hdmi_group=1
#hdmi_mode=1

# uncomment to force a HDMI mode rather than DVI. This can make audio work in
# DMT (computer monitor) modes
#hdmi_drive=2

# uncomment to increase signal to HDMI, if you have interference, blanking, or
# no display
#config_hdmi_boost=4

# uncomment for composite PAL
#sdtv_mode=2

#uncomment to overclock the arm. 700 MHz is the default.
arm_freq=700
core_freq=250
sdram_freq=400
over_voltage=0

# for more options see http://elinux.org/RPi_config.txt
gpu_mem=32

# disable rainbow screen
disable_splash=1

# improved audio?
disable_audio_dither=1

pi@rpi:~$ cat /boot/cmdline.txt 
dwc_otg.lpm_enable=0 dwc_otg.microframe_schedule=1 sdhci-bcm2708.enable_llm=1 console=tty1 elevator=noop rootwait rootdelay=60 luks rootro smsc95xx.turbo_mode=N

Some dumps after the hang:

pi@rpi:~$ sudo /opt/vc/bin/vcdbg reloc
Relocatable heap version 4 found at 0x1e000000
total space allocated is 12M, with 12M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

free list at 0x1ebffba0
11M free memory in 9 free block(s)
largest free block is 11M bytes

0x1e000000: free 11M
[   8] 0x1eb612e0: used 4.3K (refcount 1 lock count 0, size     4264, align   32, data 0x1eb61300, d0rual) 'audio_server'
0x1eb623e0: free 5.6K
[  36] 0x1eb63a40: used 2.3K (refcount 1 lock count 0, size     2316, align   32, data 0x1eb63a60, d0rual) 'audio_server'
[  37] 0x1eb643a0: used 1.0K (refcount 1 lock count 0, size      960, align   32, data 0x1eb643c0, d0rual) 'audio_server'
[  31] 0x1eb647a0: used  928 (refcount 1 lock count 0, size      848, align   32, data 0x1eb647c0, d0rual) 'audio_server'
[  30] 0x1eb64b40: used 2.9K (refcount 1 lock count 0, size     2876, align   32, data 0x1eb64b60, d0rual) 'audio_server'
[  18] 0x1eb656c0: used 3.6K (refcount 1 lock count 0, size     3600, align   32, data 0x1eb656e0, d0rual) 'audio_server'
0x1eb66520: free 768
[  12] 0x1eb66820: used 1.8K (refcount 1 lock count 0, size     1796, align   32, data 0x1eb66840, d0rual) 'audio_server'
[  20] 0x1eb66f80: used 1.8K (refcount 1 lock count 0, size     1732, align   32, data 0x1eb66fa0, d0rual) 'audio_server'
[  35] 0x1eb676a0: used 3.2K (refcount 1 lock count 0, size     3184, align   32, data 0x1eb676c0, d0rual) 'audio_server'
0x1eb68360: free 224
[  34] 0x1eb68440: used 3.2K (refcount 1 lock count 0, size     3164, align   32, data 0x1eb68460, d0rual) 'audio_server'
[  40] 0x1eb690e0: used 2.5K (refcount 1 lock count 0, size     2468, align   32, data 0x1eb69100, d0rual) 'audio_server'
[  26] 0x1eb69ae0: used 1.5K (refcount 1 lock count 0, size     1424, align   32, data 0x1eb69b00, d0rual) 'audio_server'
[  17] 0x1eb6a0c0: used 3.5K (refcount 1 lock count 0, size     3540, align   32, data 0x1eb6a0e0, d0rual) 'audio_server'
0x1eb6aee0: free 1.8K
[  10] 0x1eb6b640: used 1.3K (refcount 1 lock count 0, size     1244, align   32, data 0x1eb6b660, d0rual) 'audio_server'
[  29] 0x1eb6bb60: used 3.4K (refcount 1 lock count 0, size     3364, align   32, data 0x1eb6bb80, d0rual) 'audio_server'
[  21] 0x1eb6c8e0: used 3.6K (refcount 1 lock count 0, size     3648, align   32, data 0x1eb6c900, d0rual) 'audio_server'
[  24] 0x1eb6d760: used 3.8K (refcount 1 lock count 0, size     3760, align   32, data 0x1eb6d780, d0rual) 'audio_server'
[  27] 0x1eb6e660: used 1.5K (refcount 1 lock count 0, size     1444, align   32, data 0x1eb6e680, d0rual) 'audio_server'
[   9] 0x1eb6ec60: used 2.2K (refcount 1 lock count 0, size     2140, align   32, data 0x1eb6ec80, d0rual) 'audio_server'
[  38] 0x1eb6f500: used 2.8K (refcount 1 lock count 0, size     2812, align   32, data 0x1eb6f520, d0rual) 'audio_server'
[  11] 0x1eb70040: used 1.1K (refcount 1 lock count 0, size     1024, align    4, data 0x1eb70060, d0rual) 'resample coeff table data'
0x1eb70480: free 448
[  23] 0x1eb70640: used  192 (refcount 1 lock count 0, size      112, align   32, data 0x1eb70660, d0rual) 'audio_server'
0x1eb70700: free 384
[  28] 0x1eb70880: used  736 (refcount 1 lock count 0, size      668, align   32, data 0x1eb708a0, d0rual) 'audio_server'
[  39] 0x1eb70b60: used  416 (refcount 1 lock count 0, size      340, align   32, data 0x1eb70b80, d0rual) 'audio_server'
[  32] 0x1eb70d00: used  416 (refcount 1 lock count 0, size      344, align   32, data 0x1eb70d20, d0rual) 'audio_server'
[  15] 0x1eb70ea0: used 1.0K (refcount 1 lock count 0, size      956, align   32, data 0x1eb70ec0, d0rual) 'audio_server'
0x1eb712a0: free 1.0K
[   4] 0x1eb716c0: used 537K (refcount 1 lock count 8, size   545792, align 4096, data 0x1eb72000, d3rual) 'ARM FB'
[   2] 0x1ebf7ae0: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x1ebf7b00, d0ruAl) 'audioplus_tmp_buf'
[   1] 0x1ebfbb20: used 4.0K (refcount 1 lock count 0, size        0, align 4096, data 0x1ebfc000, d1rual) 'camera fast alloc arena'
[   3] 0x1ebfcb40: used  12K (refcount 1 lock count 0, size    12270, align    1, data 0x1ebfcb60, d0rual) 'dt_blob'
0x1ebffb80: free 64
[  16] 0x1ebffbc0: used   96 (refcount 1 lock count 0, size       12, align    4, data 0x1ebffbe0, d0rual) 'resample coeff table'
[   7] 0x1ebffc20: used  416 (refcount 1 lock count 0, size      340, align    4, data 0x1ebffc40, d0rual) 'resample context'
[   5] 0x1ebffdc0: used  576 (refcount 1 lock count 0, size      512, align    4, data 0x1ebffde0, d0rual) 'ILCS VC buffer pool'
small allocs not requested
pi@rpi:~$ sudo /opt/vc/bin/vcdbg log msg
000792.910: HDMI:EDID error reading EDID block 0 attempt 0
000794.174: HDMI:EDID error reading EDID block 0 attempt 1
000795.433: HDMI:EDID error reading EDID block 0 attempt 2
000796.691: HDMI:EDID error reading EDID block 0 attempt 3
000797.950: HDMI:EDID error reading EDID block 0 attempt 4
000799.209: HDMI:EDID error reading EDID block 0 attempt 5
000800.468: HDMI:EDID error reading EDID block 0 attempt 6
000801.727: HDMI:EDID error reading EDID block 0 attempt 7
000802.985: HDMI:EDID error reading EDID block 0 attempt 8
000804.244: HDMI:EDID error reading EDID block 0 attempt 9
000805.266: HDMI:EDID giving up on reading EDID block 0
000808.577: HDMI:Setting property pixel encoding to Default
000808.598: HDMI:Setting property pixel clock type to PAL
000808.617: HDMI:Setting property content type flag to No data
000808.638: HDMI:Setting property fuzzy format match to enabled
000816.983: gpioman: gpioman_get_pin_num: pin LEDS_RUNNING not defined
000817.006: gpioman: gpioman_get_pin_num: pin LEDS_NAND_ACTIVITY not defined
000817.027: gpioman: gpioman_get_pin_num: pin LEDS_USB_ACTIVITY not defined
000817.048: gpioman: gpioman_get_pin_num: pin LEDS_FATAL_ERROR not defined
000817.069: gpioman: gpioman_get_pin_num: pin LEDS_APP_OK not defined
000817.091: gpioman: gpioman_get_pin_num: pin LEDS_APP_FAILED not defined
000817.110: gpioman: gpioman_get_pin_num: pin LEDS_HDCP_AUTH not defined
000817.132: gpioman: gpioman_get_pin_num: pin LEDS_HDCP_UNAUTH not defined
000817.154: gpioman: gpioman_get_pin_num: pin LEDS_HDMI_ON not defined
000817.175: gpioman: gpioman_get_pin_num: pin LEDS_DVI_ON not defined
000817.196: gpioman: gpioman_get_pin_num: pin LEDS_HDMI_HPD_UP not defined
000817.217: gpioman: gpioman_get_pin_num: pin LEDS_REMOTE_CONTROL not defined
000817.238: gpioman: gpioman_get_pin_num: pin LEDS_ARM_CONTROLLED not defined
000822.208: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
000822.234: hdmi: HDMI:>>>>>>>>>>>>>Rx sensed, reading EDID<<<<<<<<<<<<<
000822.618: hdmi: HDMI:EDID error reading EDID block 0 attempt 0
000823.887: hdmi: HDMI:EDID error reading EDID block 0 attempt 1
000825.151: hdmi: HDMI:EDID error reading EDID block 0 attempt 2
000826.415: hdmi: HDMI:EDID error reading EDID block 0 attempt 3
000827.679: hdmi: HDMI:EDID error reading EDID block 0 attempt 4
000828.943: hdmi: HDMI:EDID error reading EDID block 0 attempt 5
000830.207: hdmi: HDMI:EDID error reading EDID block 0 attempt 6
000831.471: hdmi: HDMI:EDID error reading EDID block 0 attempt 7
000832.735: hdmi: HDMI:EDID error reading EDID block 0 attempt 8
000833.999: hdmi: HDMI:EDID error reading EDID block 0 attempt 9
000835.026: hdmi: HDMI:EDID giving up on reading EDID block 0
000835.054: hdmi: HDMI: No lookup table for resolution group 0
000835.072: hdmi: HDMI: hotplug attached with DVI support
000835.131: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
000835.489: hdmi: HDMI:EDID error reading EDID block 0 attempt 0
000836.750: hdmi: HDMI:EDID error reading EDID block 0 attempt 1
000838.013: hdmi: HDMI:EDID error reading EDID block 0 attempt 2
000839.275: hdmi: HDMI:EDID error reading EDID block 0 attempt 3
000840.537: hdmi: HDMI:EDID error reading EDID block 0 attempt 4
000841.799: hdmi: HDMI:EDID error reading EDID block 0 attempt 5
000843.061: hdmi: HDMI:EDID error reading EDID block 0 attempt 6
000844.323: hdmi: HDMI:EDID error reading EDID block 0 attempt 7
000845.585: hdmi: HDMI:EDID error reading EDID block 0 attempt 8
000846.847: hdmi: HDMI:EDID error reading EDID block 0 attempt 9
000847.872: hdmi: HDMI:EDID giving up on reading EDID block 0
000847.930: hdmi: HDMI: hotplug deassert
000847.945: hdmi: HDMI: HDMI is currently off
000847.960: hdmi: HDMI: changing mode to unplugged
000847.983: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
000848.562: *** Restart logging

000850.393: Read command line from file 'cmdline.txt'
dwc_otg.lpm_enable=0 dwc_otg.microframe_schedule=1 sdhci-bcm2708.enable_llm=1 console=tty1 elevator=noop rootwait rootdelay=60 luks rootro smsc95xx.turbo_mode=N

000855.219: Loading 'kernel_custom.img' from SD card
001490.184: No kernel trailer (run mkknlimg to fix) - assuming not DT-capable
001492.010: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
004579.684: vchiq_core: vchiq_init_state: slot_zero = 0x5d800000, is_master = 1
004583.911: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
004588.307: gpioman: gpioman_get_pin_num: pin LEDS_RUNNING not defined
004588.335: gpioman: gpioman_get_pin_num: pin LEDS_NAND_ACTIVITY not defined
004588.360: gpioman: gpioman_get_pin_num: pin LEDS_USB_ACTIVITY not defined
004588.384: gpioman: gpioman_get_pin_num: pin LEDS_FATAL_ERROR not defined
004588.405: gpioman: gpioman_get_pin_num: pin LEDS_APP_OK not defined
004588.426: gpioman: gpioman_get_pin_num: pin LEDS_APP_FAILED not defined
004588.448: gpioman: gpioman_get_pin_num: pin LEDS_HDCP_AUTH not defined
004588.468: gpioman: gpioman_get_pin_num: pin LEDS_HDCP_UNAUTH not defined
004588.487: gpioman: gpioman_get_pin_num: pin LEDS_HDMI_ON not defined
004588.508: gpioman: gpioman_get_pin_num: pin LEDS_DVI_ON not defined
004588.528: gpioman: gpioman_get_pin_num: pin LEDS_HDMI_HPD_UP not defined
004588.550: gpioman: gpioman_get_pin_num: pin LEDS_REMOTE_CONTROL not defined
004588.573: gpioman: gpioman_get_pin_num: pin LEDS_ARM_CONTROLLED not defined

pi@rpi:~$ sudo /opt/vc/bin/vcdbg malloc
Pool 0x9f2d7978 (1ee60ef8)
Malloc pool size=13M (pool=0x1f2d7978-0x1ff7ff2c)
0x1f2d79a0 = malloc(128K) [call from 0x1eda0896]
0x1f2f79c0 = malloc(8)    [call from 0x1ed51d6c]
0x1f2f8000 = malloc(138K) [call from 0x1ec88400]
0x1f31b320 = malloc(512)  [v3d_gfxh16_thre]
0x1f31b540 = malloc(7.1K) [dma_transfer_xfers]
0x1f31d1e0 = malloc(7.0K) [Gencmd service state]
0x1f31ee20 = malloc(180)  [vcos_cmd_entries]
0x1f31ef00 = malloc(4.0K) [reaper]
0x1f31ff20 = malloc(8.0K) [call from 0x1ee128bc]
0x1f321f40 = malloc(100)  [call from 0x1ee128d8]
0x1f321fe0 = malloc(32K)  [call from 0x1ecce322]
0x1f32a000 = malloc(512)  [call from 0x1ed35518]
0x1f32a220 = malloc(272)  [call from 0x1ecce410]
0x1f32a360 = malloc(272)  [call from 0x1ecce410]
0x1f32a4a0 = malloc(272)  [call from 0x1ecce410]
0x1f32a5e0 = malloc(272)  [call from 0x1ecce410]
0x1f32a720 = malloc(272)  [call from 0x1ecce410]
0x1f32a860 = malloc(272)  [call from 0x1ecce410]
0x1f32a9a0 = malloc(272)  [call from 0x1ecce410]
0x1f32aae0 = malloc(272)  [call from 0x1ecce410]
0x1f32ac20 = malloc(272)  [call from 0x1ecce410]
0x1f32ad60 = malloc(272)  [call from 0x1ecce410]
0x1f32aea0 = malloc(272)  [call from 0x1ecce410]
0x1f32afe0 = malloc(272)  [call from 0x1ecce410]
0x1f32b120 = malloc(272)  [call from 0x1ecce410]
0x1f32b260 = malloc(272)  [call from 0x1ecce410]
0x1f32b3a0 = malloc(272)  [call from 0x1ecce410]
0x1f32b4e0 = malloc(272)  [call from 0x1ecce410]
0x1f32b620 = malloc(272)  [call from 0x1ecce410]
0x1f32b760 = malloc(272)  [call from 0x1ecce410]
0x1f32b8a0 = malloc(272)  [call from 0x1ecce410]
0x1f32b9e0 = malloc(272)  [call from 0x1ecce410]
0x1f32bb20 = malloc(272)  [call from 0x1ecce410]
0x1f32bc60 = malloc(272)  [call from 0x1ecce410]
0x1f32bda0 = malloc(272)  [call from 0x1ecce410]
0x1f32bee0 = malloc(272)  [call from 0x1ecce410]
0x1f32c020 = malloc(272)  [call from 0x1ecce410]
0x1f32c160 = malloc(272)  [call from 0x1ecce410]
0x1f32c2a0 = malloc(272)  [call from 0x1ecce410]
0x1f32c3e0 = malloc(272)  [call from 0x1ecce410]
0x1f32c520 = malloc(272)  [call from 0x1ecce410]
0x1f32c660 = malloc(272)  [call from 0x1ecce410]
0x1f32c7a0 = malloc(272)  [call from 0x1ecce410]
0x1f32c8e0 = malloc(272)  [call from 0x1ecce410]
0x1f32ca20 = malloc(272)  [call from 0x1ecce410]
0x1f32cb60 = malloc(272)  [call from 0x1ecce410]
0x1f32cca0 = malloc(272)  [call from 0x1ecce410]
0x1f32cde0 = malloc(272)  [call from 0x1ecce410]
0x1f32cf20 = malloc(272)  [call from 0x1ecce410]
0x1f32d060 = malloc(272)  [call from 0x1ecce410]
0x1f32d1a0 = malloc(272)  [call from 0x1ecce410]
0x1f32d2e0 = malloc(272)  [call from 0x1ecce410]
0x1f32d420 = malloc(272)  [call from 0x1ecce410]
0x1f32d560 = malloc(272)  [call from 0x1ecce410]
0x1f32d6a0 = malloc(272)  [call from 0x1ecce410]
0x1f32d7e0 = malloc(272)  [call from 0x1ecce410]
0x1f32d920 = malloc(272)  [call from 0x1ecce410]
0x1f32da60 = malloc(272)  [call from 0x1ecce410]
0x1f32dba0 = malloc(272)  [call from 0x1ecce410]
0x1f32dce0 = malloc(272)  [call from 0x1ecce410]
0x1f32de20 = malloc(272)  [call from 0x1ecce410]
0x1f32df60 = malloc(272)  [call from 0x1ecce410]
0x1f32e0a0 = malloc(512)  [call from 0x1ec5de1c]
0x1f32e2c0 = malloc(16K)  [call from 0x1ec5de4e]
0x1f3322e0 = malloc(4.0K) [call from 0x1ec5deaa]
0x1f333300 = malloc(4.0K) [call from 0x1ed1a704]
0x1f334320 = malloc(4.0K) [call from 0x1ed1a730]
0x1f335340 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f3353a0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f335400 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f335460 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f3354c0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f335520 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f335580 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f3355e0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f335640 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f3356a0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f335700 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f335760 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f3357c0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f335820 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f335880 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f3358e0 = malloc(8)    [call from 0x1ec7ac82]
0x1f335920 = malloc(4.0K) [powerman]
0x1f336940 = malloc(3.0K) [call from 0x1eca8afa]
0x1f337560 = malloc(356K) [call from 0x1eca8b30]
0x1f390580 = malloc(356K) [call from 0x1eca8b6a]
0x1f3e95a0 = malloc(66K)  [call from 0x1eca8bac]
0x1f3f9d80 = malloc(1.1K) [call from 0x1edd1ad4]
0x1f3fa200 = malloc(16K)  [call from 0x1ec74642]
0x1f3fe220 = malloc(16K)  [mbox_read]
0x1f402240 = malloc(4.0K) [display_update]
0x1f403260 = malloc(4.0K) [temp_check]
0x1f404280 = malloc(16K)  [vchiq dma_xfer]
0x1f408340 = malloc(16K)  [vchiq dma_xfer]
0x1f40c400 = malloc(16K)  [vchiq dma_xfer]
0x1f4104c0 = malloc(16K)  [vchiq dma_xfer]
0x1f414580 = malloc(8.0K) [VCHIQ-0]
0x1f4165a0 = malloc(8.0K) [VCHIQr-0]
0x1f4185c0 = malloc(8.0K) [VCHIQs-0]
0x1f41a5e0 = malloc(56)   [imageconv stats]
0x1f41a640 = malloc(36)   [vchiq_shim]
0x1f41a6a0 = malloc(256)  [vchiu_queue_init]
0x1f41a7c0 = malloc(476)  [VCHIQ service]
0x1f41a9c0 = malloc(36)   [vchiq_shim]
0x1f41aa20 = malloc(256)  [vchiu_queue_init]
0x1f41ab40 = malloc(476)  [VCHIQ service]
0x1f41ad40 = malloc(36)   [vchiq_shim]
0x1f41ada0 = malloc(256)  [vchiu_queue_init]
0x1f41aec0 = malloc(476)  [VCHIQ service]
0x1f41b0c0 = malloc(2.0K) [call from 0x1ee128bc]
0x1f41b8c0 = malloc(100)  [call from 0x1ee128d8]
0x1f41b960 = malloc(4.0K) [GCMD_V]
0x1f41c980 = malloc(2.0K) [HAUDVCHI]
0x1f41d1a0 = malloc(36)   [vchiq_shim]
0x1f41d200 = malloc(256)  [vchiu_queue_init]
0x1f41d320 = malloc(476)  [VCHIQ service]
0x1f41d520 = malloc(21K)  [ILCS State]
0x1f4227e0 = malloc(256)  [vchiu_queue_init]
0x1f422900 = malloc(476)  [VCHIQ service]
0x1f422b00 = malloc(52)   [ILCS_VC_COMMON]
0x1f422b60 = malloc(4.0K) [ILCS_VC]
0x1f423b80 = malloc(3.0K) [call from 0x1eddafce]
0x1f4247a0 = malloc(36)   [vchiq_shim]
0x1f424800 = malloc(256)  [vchiu_queue_init]
0x1f424920 = malloc(476)  [VCHIQ service]
0x1f424b20 = malloc(36)   [vchiq_shim]
0x1f424b80 = malloc(256)  [vchiu_queue_init]
0x1f424ca0 = malloc(476)  [VCHIQ service]
0x1f424ea0 = malloc(36)   [vchiq_shim]
0x1f424f00 = malloc(256)  [vchiu_queue_init]
0x1f425020 = malloc(476)  [VCHIQ service]
0x1f425220 = malloc(3.0K) [call from 0x1eddb042]
0x1f425e40 = malloc(36)   [vchiq_shim]
0x1f425ea0 = malloc(256)  [vchiu_queue_init]
0x1f425fc0 = malloc(476)  [VCHIQ service]
0x1f4261c0 = malloc(36)   [vchiq_shim]
0x1f426220 = malloc(256)  [vchiu_queue_init]
0x1f426340 = malloc(476)  [VCHIQ service]
0x1f426540 = malloc(36)   [vchiq_shim]
0x1f4265a0 = malloc(256)  [vchiu_queue_init]
0x1f4266c0 = malloc(476)  [VCHIQ service]
0x1f4268c0 = malloc(60)   [call from 0x1ed4a584]
0x1f426920 = malloc(16K)  [vchiu_queue_init]
0x1f42a940 = malloc(476)  [VCHIQ service]
0x1f42ab40 = malloc(60)   [call from 0x1ed4a584]
0x1f42aba0 = malloc(16K)  [vchiu_queue_init]
0x1f42ebc0 = malloc(476)  [VCHIQ service]
0x1f42edc0 = malloc(60)   [call from 0x1ed4a584]
0x1f42ee20 = malloc(16K)  [vchiu_queue_init]
0x1f432e40 = malloc(476)  [VCHIQ service]
0x1f433040 = malloc(476)  [VCHIQ service]
0x1f433240 = malloc(320K) [KHRN_S]
0x1f483260 = malloc(36)   [vchiq_shim]
0x1f4832c0 = malloc(256)  [vchiu_queue_init]
0x1f4833e0 = malloc(476)  [VCHIQ service]
0x1f4835e0 = malloc(4.0K) [HREQ task]
0x1f484600 = malloc(4.6K) [call from 0x1eddb104]
0x1f485880 = malloc(4.0K) [FILESERV]
0x1f4868a0 = malloc(36)   [vchiq_shim]
0x1f486900 = malloc(256)  [vchiu_queue_init]
0x1f486a20 = malloc(476)  [VCHIQ service]
0x1f486c20 = malloc(608)  [Shared Memory Service]
0x1f486ea0 = malloc(4.0K) [sm_thread]
0x1f487ec0 = malloc(36)   [vchiq_shim]
0x1f487f20 = malloc(256)  [vchiu_queue_init]
0x1f488040 = malloc(476)  [VCHIQ service]
0x1f488240 = malloc(488)  [Shared Memory Cache Test]
0x1f488460 = malloc(4.0K) [smct_thread]
0x1f489480 = malloc(36)   [vchiq_shim]
0x1f4894e0 = malloc(256)  [vchiu_queue_init]
0x1f489600 = malloc(476)  [VCHIQ service]
0x1f489800 = malloc(1.3K) [CEA modes table]
0x1f489d40 = malloc(1.7K) [DMT modes table]
0x1f48a440 = malloc(4.0K) [call from 0x1eddbed6]
0x1f48b460 = malloc(36)   [vchiq_shim]
0x1f48b4c0 = malloc(256)  [vchiu_queue_init]
0x1f48b5e0 = malloc(476)  [VCHIQ service]
0x1f48b7e0 = malloc(36)   [vchiq_shim]
0x1f48b840 = malloc(256)  [vchiu_queue_init]
0x1f48b960 = malloc(476)  [VCHIQ service]
0x1f48bb60 = malloc(36)   [vchiq_shim]
0x1f48bbc0 = malloc(256)  [vchiu_queue_init]
0x1f48bce0 = malloc(476)  [VCHIQ service]
0x1f48bee0 = malloc(4.0K) [call from 0x1eddbf52]
0x1f48cf00 = malloc(36)   [vchiq_shim]
0x1f48cf60 = malloc(256)  [vchiu_queue_init]
0x1f48d080 = malloc(476)  [VCHIQ service]
0x1f48d280 = malloc(36)   [vchiq_shim]
0x1f48d2e0 = malloc(256)  [vchiu_queue_init]
0x1f48d400 = malloc(476)  [VCHIQ service]
0x1f48d600 = malloc(36)   [vchiq_shim]
0x1f48d660 = malloc(256)  [vchiu_queue_init]
0x1f48d780 = malloc(476)  [VCHIQ service]
0x1f48d980 = malloc(4.0K) []
0x1f48e9a0 = malloc(36)   [vchiq_shim]
0x1f48ea00 = malloc(256)  [vchiu_queue_init]
0x1f48eb20 = malloc(476)  [VCHIQ service]
0x1f48ed20 = malloc(36)   [vchiq_shim]
0x1f48ed80 = malloc(256)  [vchiu_queue_init]
0x1f48eea0 = malloc(476)  [VCHIQ service]
0x1f48f0a0 = malloc(36)   [vchiq_shim]
0x1f48f100 = malloc(256)  [vchiu_queue_init]
0x1f48f220 = malloc(476)  [VCHIQ service]
0x1f48f420 = malloc(4.0K) []
0x1f490440 = malloc(36)   [vchiq_shim]
0x1f4904a0 = malloc(256)  [vchiu_queue_init]
0x1f4905c0 = malloc(476)  [VCHIQ service]
0x1f4907c0 = malloc(36)   [vchiq_shim]
0x1f490820 = malloc(256)  [vchiu_queue_init]
0x1f490940 = malloc(476)  [VCHIQ service]
0x1f490b40 = malloc(36)   [vchiq_shim]
0x1f490ba0 = malloc(256)  [vchiu_queue_init]
0x1f490cc0 = malloc(476)  [VCHIQ service]
0x1f490ec0 = malloc(36)   [vchiq_shim]
0x1f490f20 = malloc(256)  [vchiu_queue_init]
0x1f491040 = malloc(476)  [VCHIQ service]
0x1f491240 = malloc(36)   [vchiq_shim]
0x1f4912a0 = malloc(256)  [vchiu_queue_init]
0x1f4913c0 = malloc(476)  [VCHIQ service]
0x1f4915c0 = malloc(36)   [vchiq_shim]
0x1f491620 = malloc(256)  [vchiu_queue_init]
0x1f491740 = malloc(476)  [VCHIQ service]
0x1f491940 = malloc(36)   [vchiq_shim]
0x1f4919a0 = malloc(256)  [vchiu_queue_init]
0x1f491ac0 = malloc(476)  [VCHIQ service]
0x1f491cc0 = malloc(36)   [vchiq_shim]
0x1f491d20 = malloc(256)  [vchiu_queue_init]
0x1f491e40 = malloc(476)  [VCHIQ service]
0x1f492040 = malloc(36)   [vchiq_shim]
0x1f4920a0 = malloc(256)  [vchiu_queue_init]
0x1f4921c0 = malloc(476)  [VCHIQ service]
0x1f4923c0 = malloc(36)   [vchiq_shim]
0x1f492420 = malloc(256)  [vchiu_queue_init]
0x1f492540 = malloc(476)  [VCHIQ service]
0x1f492740 = malloc(36)   [vchiq_shim]
0x1f4927a0 = malloc(256)  [vchiu_queue_init]
0x1f4928c0 = malloc(476)  [VCHIQ service]
0x1f492ac0 = malloc(476)  [VCHIQ service]
0x1f492cc0 = malloc(476)  [VCHIQ service]
0x1f492ec0 = malloc(476)  [VCHIQ service]
0x1f4930c0 = malloc(476)  [VCHIQ service]
0x1f4932c0 = malloc(476)  [VCHIQ service]
0x1f4934c0 = malloc(476)  [VCHIQ service]
0x1f4936c0 = malloc(476)  [VCHIQ service]
0x1f4938c0 = malloc(476)  [VCHIQ service]
0x1f493ac0 = malloc(476)  [VCHIQ service]
0x1f493cc0 = malloc(476)  [VCHIQ service]
0x1f493ec0 = malloc(4.3K) [mmal debug log]
0x1f495000 = malloc(16K)  [mmal_host_log]
0x1f499040 = malloc(512)  [vchiu_queue_init]
0x1f499260 = malloc(476)  [VCHIQ service]
0x1f499460 = malloc(40)   [call from 0x1ed5b7e2]
0x1f4994c0 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499520 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499580 = malloc(40)   [call from 0x1ed5b7e2]
0x1f4995e0 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499640 = malloc(40)   [call from 0x1ed5b7e2]
0x1f4996a0 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499700 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499760 = malloc(40)   [call from 0x1ed5b7e2]
0x1f4997c0 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499820 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499880 = malloc(40)   [call from 0x1ed5b7e2]
0x1f4998e0 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499940 = malloc(40)   [call from 0x1ed5b7e2]
0x1f4999a0 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499a00 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499a60 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499ac0 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499b20 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499b80 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499be0 = malloc(40)   [call from 0x1ed5b7e2]
0x1f499c40 = malloc(256)  [mmal msg queue mem]
0x1f499d60 = malloc(4.0K) [mmal msg queue ]
0x1f49ad80 = malloc(4.0K) [mmal msg queue ]
0x1f49bda0 = malloc(4.0K) [mmal worker]
0x1f49cdc0 = malloc(476)  [VCHIQ service]
0x1f49cfc0 = malloc(4.0K) [vc watchdog]
0x1f49dfe0 = malloc(1.0K) [call from 0x1ed85f70]
0x1f49e400 = malloc(128K) [call from 0x1ed86012]
0x1f4be410 = hole(11M)
Malloced:1.9M Remaining:11M
root@rpi:/home/pi# dmesg 
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 3.18.9-v6+ (root@1f6f48728e28) (gcc version 4.7.1 20120402 (prerelease) (crosstool-NG 1.15.2) ) #3 PREEMPT Thu Mar 19 09:58:16 UTC 2015
[    0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
[    0.000000] Machine: BCM2708
[    0.000000] cma: Reserved 8 MiB at 0x1d800000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] On node 0 totalpages: 122880
[    0.000000] free_area_init_node: node 0, pgdat c0c833ac, node_mem_map dd434000
[    0.000000]   Normal zone: 960 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 122880 pages, LIFO batch:31
[    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 121920
[    0.000000] Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708.boardrev=0x10 bcm2708.serial=0x7c40f775 smsc95xx.macaddr=B8:27:EB:40:F7:75 bcm2708_fb.fbswap=1 bcm2708.disk_led_gpio=47 bcm2708.disk_led_active_low=0 sdhci-bcm2708.emmc_clock_freq=250000000 vc_mem.mem_base=0x1ec00000 vc_mem.mem_size=0x20000000  dwc_otg.lpm_enable=0 dwc_otg.microframe_schedule=1 sdhci-bcm2708.enable_llm=1 console=tty1 elevator=noop rootwait rootdelay=60 luks rootro smsc95xx.turbo_mode=N
[    0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Memory: 465420K/491520K available (7100K kernel code, 376K rwdata, 2108K rodata, 3228K init, 752K bss, 26100K reserved)
[    0.000000] Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xffe00000   (2048 kB)
    vmalloc : 0xde800000 - 0xff000000   ( 520 MB)
    lowmem  : 0xc0000000 - 0xde000000   ( 480 MB)
    modules : 0xbf000000 - 0xc0000000   (  16 MB)
      .text : 0xc0008000 - 0xc0906528   (9210 kB)
      .init : 0xc0907000 - 0xc0c2e000   (3228 kB)
      .data : 0xc0c2e000 - 0xc0c8c374   ( 377 kB)
       .bss : 0xc0c8c374 - 0xc0d486f8   ( 753 kB)
[    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000] NR_IRQS:522
[    0.000025] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 2147483648000ns
[    0.000076] Switching to timer-based delay loop, resolution 1000ns
[    0.000361] Console: colour dummy device 80x30
[    0.001682] console [tty1] enabled
[    0.001733] Calibrating delay loop (skipped), value calculated using timer frequency.. 2.00 BogoMIPS (lpj=10000)
[    0.001817] pid_max: default: 32768 minimum: 301
[    0.002224] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.002298] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.003441] Initializing cgroup subsys memory
[    0.003543] Initializing cgroup subsys devices
[    0.003605] Initializing cgroup subsys freezer
[    0.003663] Initializing cgroup subsys net_cls
[    0.003718] Initializing cgroup subsys blkio
[    0.003769] Initializing cgroup subsys perf_event
[    0.003825] Initializing cgroup subsys net_prio
[    0.003978] CPU: Testing write buffer coherency: ok
[    0.004096] ftrace: allocating 22259 entries in 66 pages
[    0.123572] Setting up static identity map for 0x673548 - 0x6735a4
[    0.126421] devtmpfs: initialized
[    0.144502] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
[    0.147942] xor: measuring software checksum speed
[    0.243372]    arm4regs  :   972.400 MB/sec
[    0.343449]    8regs     :   470.400 MB/sec
[    0.443587]    32regs    :   416.400 MB/sec
[    0.443640] xor: using function: arm4regs (972.400 MB/sec)
[    0.443726] pinctrl core: initialized pinctrl subsystem
[    0.444675] NET: Registered protocol family 16
[    0.450254] DMA: preallocated 4096 KiB pool for atomic coherent allocations
[    0.473727] cpuidle: using governor ladder
[    0.503788] cpuidle: using governor menu
[    0.504552] bcm2708.uart_clock = 3000000
[    0.504654] of_platform_populate failed: -22
[    0.507610] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
[    0.507685] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.507756] mailbox: Broadcom VideoCore Mailbox driver
[    0.507916] bcm2708_vcio: mailbox at f200b880
[    0.508426] bcm_power: Broadcom power driver
[    0.508486] bcm_power_open() -> 0
[    0.508519] bcm_power_request(0, 8)
[    1.009232] bcm_mailbox_read -> 00000080, 0
[    1.009285] bcm_power_request -> 0
[    1.009498] Serial: AMBA PL011 UART driver
[    1.009717] dev:f1: ttyAMA0 at MMIO 0x20201000 (irq = 83, base_baud = 0) is a PL011 rev3
[    1.246064] raid6: int32x1     46 MB/s
[    1.415917] raid6: int32x2     66 MB/s
[    1.586081] raid6: int32x4     88 MB/s
[    1.756397] raid6: int32x8    100 MB/s
[    1.756455] raid6: using algorithm int32x8 (100 MB/s)
[    1.756493] raid6: using intx1 recovery algorithm
[    1.757330] SCSI subsystem initialized
[    1.757724] usbcore: registered new interface driver usbfs
[    1.757893] usbcore: registered new interface driver hub
[    1.758126] usbcore: registered new device driver usb
[    1.760483] Switched to clocksource stc
[    1.792017] FS-Cache: Loaded
[    1.792468] CacheFiles: Loaded
[    3.742750] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.747663] smsc95xx v1.0.4
[    3.805224] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:40:f7:75
[    3.900671] usb 1-1.3: new full-speed USB device number 4 using dwc_otg
[    4.027461] usb 1-1.3: New USB device found, idVendor=0403, idProduct=6015
[    4.029415] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    4.031317] usb 1-1.3: Product: FT231X USB UART
[    4.033097] usb 1-1.3: Manufacturer: FTDI
[    4.034809] usb 1-1.3: SerialNumber: DA00S2VB
[    4.756544] BTRFS: device label btrfs_root devid 1 transid 26752 /dev/mapper/luks-root
[    4.763729] BTRFS info (device dm-0): turning on discard
[    4.765617] BTRFS info (device dm-0): use ssd allocation scheme
[    4.767351] BTRFS info (device dm-0): enabling auto defrag
[    4.769100] BTRFS info (device dm-0): disk space caching is enabled
[    5.641472] random: systemd urandom read with 77 bits of entropy available
[    5.649815] systemd[1]: systemd 215 running in system mode. (+PAM +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ -SECCOMP -APPARMOR)
[    5.654468] systemd[1]: Detected architecture 'arm'.
[    5.880053] NET: Registered protocol family 10
[    5.884248] systemd[1]: Inserted module 'ipv6'
[    5.887955] systemd[1]: Set hostname to <rpi>.
[    6.203597] systemd-gpt-auto-generator[115]: Failed to determine block device of root file system: No such file or directory
[    6.224158] systemd[109]: /lib/systemd/system-generators/systemd-gpt-auto-generator failed with error code 1.
[    6.575315] systemd[1]: Cannot add dependency job for unit display-manager.service, ignoring: Unit display-manager.service failed to load: No such file or directory.
[    6.586966] systemd[1]: Starting Forward Password Requests to Wall Directory Watch.
[    6.592096] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    6.596420] systemd[1]: Starting Remote File Systems (Pre).
[    6.601632] systemd[1]: Reached target Remote File Systems (Pre).
[    6.603950] systemd[1]: Expecting device dev-modem2.device...
[    6.609060] systemd[1]: Starting Arbitrary Executable File Formats File System Automount Point.
[    6.617468] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    6.622357] systemd[1]: Starting Encrypted Volumes.
[    6.627646] systemd[1]: Reached target Encrypted Volumes.
[    6.630033] systemd[1]: Starting Swap.
[    6.635300] systemd[1]: Reached target Swap.
[    6.637546] systemd[1]: Expecting device dev-mmcblk0p1.device...
[    6.642494] systemd[1]: Starting Root Slice.
[    6.756839] systemd[1]: Created slice Root Slice.
[    6.758915] systemd[1]: Starting /dev/initctl Compatibility Named Pipe.
[    6.764125] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    6.766290] systemd[1]: Starting Delayed Shutdown Socket.
[    6.771479] systemd[1]: Listening on Delayed Shutdown Socket.
[    6.773579] systemd[1]: Starting Journal Socket (/dev/log).
[    6.778394] systemd[1]: Listening on Journal Socket (/dev/log).
[    6.780455] systemd[1]: Starting udev Control Socket.
[    6.785297] systemd[1]: Listening on udev Control Socket.
[    6.787322] systemd[1]: Starting udev Kernel Socket.
[    6.792057] systemd[1]: Listening on udev Kernel Socket.
[    6.794110] systemd[1]: Starting Journal Socket.
[    6.798847] systemd[1]: Listening on Journal Socket.
[    6.801203] systemd[1]: Starting System Slice.
[    6.808214] systemd[1]: Created slice System Slice.
[    6.810898] systemd[1]: Mounting Temporary Directory...
[    6.815227] systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway.
[    6.823944] systemd[1]: Starting system-getty.slice.
[    6.842197] systemd[1]: Created slice system-getty.slice.
[    6.844547] systemd[1]: Mounted Huge Pages File System.
[    6.846541] systemd[1]: Mounting POSIX Message Queue File System...
[    6.865401] systemd[1]: Starting Create list of required static device nodes for the current kernel...
[    6.917409] systemd[1]: Mounting Debug File System...
[    7.061445] systemd[1]: Started Set Up Additional Binary Formats.
[    7.071811] systemd[1]: Starting Load Kernel Modules...
[    7.087575] systemd[1]: Starting udev Coldplug all Devices...
[    7.126595] systemd[1]: Starting Journal Service...
[    7.191932] systemd[1]: Started Journal Service.
[    7.263340] bcm2708 watchdog, heartbeat=10 sec (nowayout=0)
[    7.731144] i2c /dev entries driver
[    8.539089] systemd-udevd[147]: starting version 215
[    9.487462] bcm2708_i2c_init_pinmode(1,2)
[    9.489098] bcm2708_i2c_init_pinmode(1,3)
[    9.508898] bcm2708_i2c bcm2708_i2c.1: BSC1 Controller at 0x20804000 (irq 79) (baudrate 100000)
[    9.777403] usbcore: registered new interface driver usbserial
[    9.779229] usbcore: registered new interface driver usbserial_generic
[    9.817464] usbserial: USB Serial support registered for generic
[    9.919560] usbcore: registered new interface driver ftdi_sio
[    9.955048] usbserial: USB Serial support registered for FTDI USB Serial Device
[    9.957274] ftdi_sio 1-1.3:1.0: FTDI USB Serial Device converter detected
[    9.959224] usb 1-1.3: Detected FT-X
[    9.991217] usb 1-1.3: FTDI USB Serial Device converter now attached to ttyUSB0
[   11.090743] BTRFS info (device dm-0): disk space caching is enabled
[   11.120701] pcm512x 1-004d: Failed to reset device: -5
[   11.122550] pcm512x: probe of 1-004d failed with error -5
[   11.125534] pcm512x 1-004c: Failed to reset device: -5
[   11.127427] pcm512x: probe of 1-004c failed with error -5
[   11.893615] systemd-journald[132]: Received request to flush runtime journal from PID 1
[   13.264261] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[   13.267112] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   13.526742] random: nonblocking pool is initialized
[   14.668838] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xDDE1
[   14.684671] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   18.430844] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
[   18.436128] ftdi_sio 1-1.3:1.0: device disconnected
[   18.537150] ftdi_sio 1-1.3:1.0: FTDI USB Serial Device converter detected
[   18.545379] usb 1-1.3: Detected FT-X
[   18.554451] usb 1-1.3: FTDI USB Serial Device converter now attached to ttyUSB0
[   19.155416] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
[   19.192907] ftdi_sio 1-1.3:1.0: device disconnected
[   19.202662] ftdi_sio 1-1.3:1.0: FTDI USB Serial Device converter detected
[   19.210911] usb 1-1.3: Detected FT-X
[   19.238182] usb 1-1.3: FTDI USB Serial Device converter now attached to ttyUSB0
[   22.852070] tun: Universal TUN/TAP device driver, 1.6
[   22.854008] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
[   43.568825] bridge: automatic filtering via arp/ip/ip6tables has been deprecated. Update your scripts to load br_netfilter if you need this.
[   43.626151] IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready
[   43.885653] ip_tables: (C) 2000-2006 Netfilter Core Team
[   44.101026] nf_conntrack version 0.5.0 (7450 buckets, 29800 max)
[  602.166089] bcm2708_fb_blank(1) returns=0 p[1]=0x80000001
[93002.138710] INFO: task cat:5216 blocked for more than 120 seconds.
[93002.138901]       Not tainted 3.18.9-v6+ #3
[93002.139008] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93002.139222] cat             D c066d058     0  5216   5215 0x00000001
[93002.139523] [<c066d058>] (__schedule) from [<c066d540>] (schedule+0x40/0x8c)
[93002.139758] [<c066d540>] (schedule) from [<c0670294>] (schedule_timeout+0x200/0x284)
[93002.140074] [<c0670294>] (schedule_timeout) from [<c066f3cc>] (__down+0x9c/0xdc)
[93002.140309] [<c066f3cc>] (__down) from [<c0058f1c>] (down+0xbc/0xc0)
[93002.140474] [<c0058f1c>] (down) from [<c001f788>] (bcm_mailbox_read+0x68/0xa0)
[93002.140653] [<c001f788>] (bcm_mailbox_read) from [<c001f894>] (bcm_mailbox_property+0xd4/0x16c)
[93002.140872] [<c001f894>] (bcm_mailbox_property) from [<c0523df8>] (bcm2835_get_temp_or_max.isra.0+0x60/0xcc)
[93002.155801] [<c0523df8>] (bcm2835_get_temp_or_max.isra.0) from [<c0523eac>] (bcm2835_get_temp+0x20/0x28)
[93002.198694] [<c0523eac>] (bcm2835_get_temp) from [<c0520b50>] (thermal_zone_get_temp+0x58/0x74)
[93002.235216] [<c0520b50>] (thermal_zone_get_temp) from [<c0520ce8>] (temp_show+0x28/0x4c)
[93002.264426] [<c0520ce8>] (temp_show) from [<c046b34c>] (dev_attr_show+0x2c/0x58)
[93002.285360] [<c046b34c>] (dev_attr_show) from [<c01b2e14>] (sysfs_kf_seq_show+0x9c/0x120)
[93002.310286] [<c01b2e14>] (sysfs_kf_seq_show) from [<c01b165c>] (kernfs_seq_show+0x34/0x38)
[93002.339735] [<c01b165c>] (kernfs_seq_show) from [<c01657c4>] (seq_read+0x1ac/0x4c4)
[93484.489827] [<c01b165c>] (kernfs_seq_show) from [<c01657c4>] (seq_read+0x1ac/0x4c4)
[93484.515183] [<c01657c4>] (seq_read) from [<c01b2194>] (kernfs_fop_read+0x11c/0x164)
[93484.543148] [<c01b2194>] (kernfs_fop_read) from [<c01420f4>] (vfs_read+0x98/0x194)
[93484.568561] [<c01420f4>] (vfs_read) from [<c014223c>] (SyS_read+0x4c/0x98)
[93484.589017] [<c014223c>] (SyS_read) from [<c000eb40>] (ret_fast_syscall+0x0/0x48)
[93604.604945] INFO: task cat:5216 blocked for more than 120 seconds.
[93604.615736]       Not tainted 3.18.9-v6+ #3
[93604.632675] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93604.663758] cat             D c066d058     0  5216   5215 0x00000001
[93604.679308] [<c066d058>] (__schedule) from [<c066d540>] (schedule+0x40/0x8c)
[93604.695335] [<c066d540>] (schedule) from [<c0670294>] (schedule_timeout+0x200/0x284)
[93604.717170] [<c0670294>] (schedule_timeout) from [<c066f3cc>] (__down+0x9c/0xdc)
[93604.742015] [<c066f3cc>] (__down) from [<c0058f1c>] (down+0xbc/0xc0)
[93604.759080] [<c0058f1c>] (down) from [<c001f788>] (bcm_mailbox_read+0x68/0xa0)
[93604.769654] [<c001f788>] (bcm_mailbox_read) from [<c001f894>] (bcm_mailbox_property+0xd4/0x16c)
[93604.793672] [<c001f894>] (bcm_mailbox_property) from [<c0523df8>] (bcm2835_get_temp_or_max.isra.0+0x60/0xcc)
[93604.822839] [<c0523df8>] (bcm2835_get_temp_or_max.isra.0) from [<c0523eac>] (bcm2835_get_temp+0x20/0x28)
[93604.843036] [<c0523eac>] (bcm2835_get_temp) from [<c0520b50>] (thermal_zone_get_temp+0x58/0x74)
[93604.868099] [<c0520b50>] (thermal_zone_get_temp) from [<c0520ce8>] (temp_show+0x28/0x4c)
[93604.890917] [<c0520ce8>] (temp_show) from [<c046b34c>] (dev_attr_show+0x2c/0x58)
[93604.915031] [<c046b34c>] (dev_attr_show) from [<c01b2e14>] (sysfs_kf_seq_show+0x9c/0x120)
[93604.944727] [<c01b2e14>] (sysfs_kf_seq_show) from [<c01b165c>] (kernfs_seq_show+0x34/0x38)
[93604.970539] [<c01b165c>] (kernfs_seq_show) from [<c01657c4>] (seq_read+0x1ac/0x4c4)
[93604.996833] [<c01657c4>] (seq_read) from [<c01b2194>] (kernfs_fop_read+0x11c/0x164)
[93605.019571] [<c01b2194>] (kernfs_fop_read) from [<c01420f4>] (vfs_read+0x98/0x194)
[93605.044957] [<c01420f4>] (vfs_read) from [<c014223c>] (SyS_read+0x4c/0x98)
[93605.065989] [<c014223c>] (SyS_read) from [<c000eb40>] (ret_fast_syscall+0x0/0x48)
[93725.096284] INFO: task cat:5216 blocked for more than 120 seconds.
[93725.107082]       Not tainted 3.18.9-v6+ #3
[93725.122101] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93725.151319] cat             D c066d058     0  5216   5215 0x00000001
[93725.162603] [<c066d058>] (__schedule) from [<c066d540>] (schedule+0x40/0x8c)
[93725.176327] [<c066d540>] (schedule) from [<c0670294>] (schedule_timeout+0x200/0x284)
[93725.206872] [<c0670294>] (schedule_timeout) from [<c066f3cc>] (__down+0x9c/0xdc)
[93725.227185] [<c066f3cc>] (__down) from [<c0058f1c>] (down+0xbc/0xc0)
[93725.241851] [<c0058f1c>] (down) from [<c001f788>] (bcm_mailbox_read+0x68/0xa0)
[93725.259203] [<c001f788>] (bcm_mailbox_read) from [<c001f894>] (bcm_mailbox_property+0xd4/0x16c)
[93725.279804] [<c001f894>] (bcm_mailbox_property) from [<c0523df8>] (bcm2835_get_temp_or_max.isra.0+0x60/0xcc)
[93725.303711] [<c0523df8>] (bcm2835_get_temp_or_max.isra.0) from [<c0523eac>] (bcm2835_get_temp+0x20/0x28)
[93725.331974] [<c0523eac>] (bcm2835_get_temp) from [<c0520b50>] (thermal_zone_get_temp+0x58/0x74)
[93725.352276] [<c0520b50>] (thermal_zone_get_temp) from [<c0520ce8>] (temp_show+0x28/0x4c)
[93725.376273] [<c0520ce8>] (temp_show) from [<c046b34c>] (dev_attr_show+0x2c/0x58)
[93725.408168] [<c046b34c>] (dev_attr_show) from [<c01b2e14>] (sysfs_kf_seq_show+0x9c/0x120)
[93725.429325] [<c01b2e14>] (sysfs_kf_seq_show) from [<c01b165c>] (kernfs_seq_show+0x34/0x38)
[93725.454470] [<c01b165c>] (kernfs_seq_show) from [<c01657c4>] (seq_read+0x1ac/0x4c4)
[93725.493848] [<c01657c4>] (seq_read) from [<c01b2194>] (kernfs_fop_read+0x11c/0x164)
[93725.515251] [<c01b2194>] (kernfs_fop_read) from [<c01420f4>] (vfs_read+0x98/0x194)
[93725.541657] [<c01420f4>] (vfs_read) from [<c014223c>] (SyS_read+0x4c/0x98)
[93725.559257] [<c014223c>] (SyS_read) from [<c000eb40>] (ret_fast_syscall+0x0/0x48)
[93845.577490] INFO: task cat:5216 blocked for more than 120 seconds.
[93845.588274]       Not tainted 3.18.9-v6+ #3
[93845.605050] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93845.637990] cat             D c066d058     0  5216   5215 0x00000001
[93845.648821] [<c066d058>] (__schedule) from [<c066d540>] (schedule+0x40/0x8c)
[93845.663423] [<c066d540>] (schedule) from [<c0670294>] (schedule_timeout+0x200/0x284)
[93845.692121] [<c0670294>] (schedule_timeout) from [<c066f3cc>] (__down+0x9c/0xdc)
[93845.712690] [<c066f3cc>] (__down) from [<c0058f1c>] (down+0xbc/0xc0)
[93845.727639] [<c0058f1c>] (down) from [<c001f788>] (bcm_mailbox_read+0x68/0xa0)
[93845.747566] [<c001f788>] (bcm_mailbox_read) from [<c001f894>] (bcm_mailbox_property+0xd4/0x16c)
[93845.773657] [<c001f894>] (bcm_mailbox_property) from [<c0523df8>] (bcm2835_get_temp_or_max.isra.0+0x60/0xcc)
[93845.798157] [<c0523df8>] (bcm2835_get_temp_or_max.isra.0) from [<c0523eac>] (bcm2835_get_temp+0x20/0x28)
[93845.818605] [<c0523eac>] (bcm2835_get_temp) from [<c0520b50>] (thermal_zone_get_temp+0x58/0x74)
[93845.842681] [<c0520b50>] (thermal_zone_get_temp) from [<c0520ce8>] (temp_show+0x28/0x4c)
[93845.871021] [<c0520ce8>] (temp_show) from [<c046b34c>] (dev_attr_show+0x2c/0x58)
[93845.891431] [<c046b34c>] (dev_attr_show) from [<c01b2e14>] (sysfs_kf_seq_show+0x9c/0x120)
[93845.916584] [<c01b2e14>] (sysfs_kf_seq_show) from [<c01b165c>] (kernfs_seq_show+0x34/0x38)
[93845.944478] [<c01b165c>] (kernfs_seq_show) from [<c01657c4>] (seq_read+0x1ac/0x4c4)
[93845.970162] [<c01657c4>] (seq_read) from [<c01b2194>] (kernfs_fop_read+0x11c/0x164)
[93845.993466] [<c01b2194>] (kernfs_fop_read) from [<c01420f4>] (vfs_read+0x98/0x194)
[93846.019636] [<c01420f4>] (vfs_read) from [<c014223c>] (SyS_read+0x4c/0x98)
[93846.033552] [<c014223c>] (SyS_read) from [<c000eb40>] (ret_fast_syscall+0x0/0x48)
[93966.058990] INFO: task cat:5216 blocked for more than 120 seconds.
[93966.070180]       Not tainted 3.18.9-v6+ #3
[93966.086000] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93966.118572] cat             D c066d058     0  5216   5215 0x00000001
[93966.129539] [<c066d058>] (__schedule) from [<c066d540>] (schedule+0x40/0x8c)
[93966.144948] [<c066d540>] (schedule) from [<c0670294>] (schedule_timeout+0x200/0x284)
[93966.175619] [<c0670294>] (schedule_timeout) from [<c066f3cc>] (__down+0x9c/0xdc)
[93966.196174] [<c066f3cc>] (__down) from [<c0058f1c>] (down+0xbc/0xc0)
[93966.210550] [<c0058f1c>] (down) from [<c001f788>] (bcm_mailbox_read+0x68/0xa0)
[93966.229954] [<c001f788>] (bcm_mailbox_read) from [<c001f894>] (bcm_mailbox_property+0xd4/0x16c)
[93966.250090] [<c001f894>] (bcm_mailbox_property) from [<c0523df8>] (bcm2835_get_temp_or_max.isra.0+0x60/0xcc)
[93966.275192] [<c0523df8>] (bcm2835_get_temp_or_max.isra.0) from [<c0523eac>] (bcm2835_get_temp+0x20/0x28)
[93966.304189] [<c0523eac>] (bcm2835_get_temp) from [<c0520b50>] (thermal_zone_get_temp+0x58/0x74)
[93966.324788] [<c0520b50>] (thermal_zone_get_temp) from [<c0520ce8>] (temp_show+0x28/0x4c)

If needed a complete 512MiB memory dump is available.

During last 3 days there are 2 broken devices out of 10 devices in the test. The reason for the hangs is unclear.

popcornmix commented 9 years ago

The latest firmware update (https://github.com/Hexxeh/rpi-firmware/commit/998327d2ee58c9a021883167207806a7624aa7bf) enabled assert logging in the vcdbg log. It would be useful if you could catch a hang with that kernel.

A repeatable sequence of commands that results in a hang would also be useful.

citiq commented 9 years ago

Updated to latest firmare, changed gpu_mem from 32 to 64 and after 15 hours of uptime so far no hangs. Running the test on 10 RPIs. At the moment following asserts were collected (same on all RPIs, assuming not critical?):

000944.290: assert( (open->periph_setup->port == I2C_PORT_0 && (open->periph_setup->sda_pin == 0 || open->periph_setup->sda_pin == 28) && (open->periph_setup->scl_pin == 1 || open->periph_setup->scl_pin == 29)) || (open->periph_setup->port == I2C_PORT_1 && (open->periph_setup->sda_pin == 2 && open->periph_setup->scl_pin == 3)) || open->periph_setup->port == I2C_PORT_2 ) failed; ../../../../../vcfw/drivers/chip/vciv/2708/i2c.c::i2c_open line 444
605082.655: assert( new_display_num != 0xff ) failed; ../../../../../middleware/dispmanx/dispmanx.c::dispmanx_display_open line 4202
605082.706: assert( s == 0 ) failed; ../../../../../helpers/arm_loader/arm_display.c::arm_display_set line 1085
605082.757: assert( s == 0 ) failed; ../../../../../helpers/arm_loader/arm_loader.c::handle_mbox_property line 2177

The issue is hard to reproduce as it was happening also on idle RPI (booted and not doing anything useful).

Continue in test, waiting if some hangs occur.

BTW: We do have a custom kernel (same config as latest raspbian but then compiled in some more options - btrfs, luks, aufs patch). We could provide a .config diff if useful.

popcornmix commented 9 years ago

Nothing too concerning in the assert log fragment. The initial I2S assert is normal. I'd be interested to know what you did to get the 3 display asserts. Something like changing the framebuffer with display turned off (tvservice -o) might do that, but it's not critical - the code should handle that gracefully.

citiq commented 9 years ago

Regarding the display asserts - at the end of boot the display is turned off - exactly as you suspected.

So far no hangs - I have a feeling that somehow gpu_mem settings (<64MB) could be the cause of the issue...

citiq commented 9 years ago

Still no GPU hangs (great!) but on some RPIs found following message invalid space 0x0 in free list at ...

sudo /opt/vc/bin/vcdbg reloc stats

Relocatable heap version 4 found at 0x1c000000
total space allocated is 44M, with 44M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

small_allocs                  : 73
allocs                        : 459126
alloc_fails                   : 0
legacy_block_fails            : 0
compactions                   : 0
discard_compactions           : 0
aggressive_compactions        : 0
aggressive_compaction_waits   : 0
aggressive_compaction_timeouts: 0
locks                         : 0
small_locks                   : 0

free list at 0x1ebffda0
invalid space 0x0 in free list at 0x1eb6eb40
7.8K free memory in 2 free block(s)
largest free block is 7.2K bytes

Could this be a hint? Or is it a harmless info? RPIs in test were playing random mp3s from java application.

popcornmix commented 9 years ago

vcdbg reads gpu memory in a cache incoherent, non-locking way, so its output needs to be taken with a pinch of salt. Always run:

vcgencmd cache_flush && sudo /opt/vc/bin/vcdbg reloc stats

and only believe it if you see the same results twice.

citiq commented 9 years ago

OK, first hang on 1 RPI:

sudo /opt/vc/bin/vcdbg log assert
...
3226740.081: assert( (interrupt_save & (1<<30)) || ((int)_tx_thread_system_state < 0) ) failed; ../../../../../vcfw/rtos/threadx/rtos_threadx_latch.c::rtos_latch_get_real line 99

What is the meaning of 3226740.081 timestamp? I'd like to match it against the systemd log to find out what was happening around that time.

sudo /opt/vc/bin/vcdbg reloc

Relocatable heap version 4 found at 0x1c000000
total space allocated is 44M, with 44M relocatable, 0 legacy and 0 offline
0 legacy blocks of size 2359296

free list at 0x1ebffda0
43M free memory in 2 free block(s)
largest free block is 43M bytes

0x1c000000: free 43M
[   4] 0x1eb716c0: used 537K (refcount 1 lock count 8, size   545792, align 4096, data 0x1eb72000, d3rual) 'ARM FB'
[   2] 0x1ebf7ae0: used  16K (refcount 1 lock count 0, size    16384, align   32, data 0x1ebf7b00, d0ruAl) 'audioplus_tmp_buf'
[   1] 0x1ebfbb20: used 4.0K (refcount 1 lock count 0, size        0, align 4096, data 0x1ebfc000, d1rual) 'camera fast alloc arena'
[   3] 0x1ebfcb40: used  12K (refcount 1 lock count 0, size    12270, align    1, data 0x1ebfcb60, d0rual) 'dt_blob'
0x1ebffb80: free 576
[   5] 0x1ebffdc0: used  576 (refcount 1 lock count 0, size      512, align    4, data 0x1ebffde0, d0rual) 'ILCS VC buffer pool'
small allocs not requested
sudo /opt/vc/bin/vcdbg malloc
Pool 0x9f3af2b8 (1eefab9c)
Malloc pool size=12M (pool=0x1f3af2b8-0x1ff7ff2c)
0x1f3af2e0 = malloc(128K) [call from 0x1ee091ac]
0x1f3cf300 = malloc(24)   [call from 0x1edaa374]
0x1f3d0000 = malloc(138K) [call from 0x1ec93c78]
0x1f3f2c60 = malloc(512)  [v3d_gfxh16_thre]
0x1f3f2e80 = malloc(7.1K) [dma_transfer_xfers]
0x1f3f4b20 = malloc(7.0K) [Gencmd service state]
0x1f3f6760 = malloc(180)  [vcos_cmd_entries]
0x1f3f6840 = malloc(4.0K) [reaper]
0x1f3f7860 = malloc(8.0K) [call from 0x1eea82b4]
0x1f3f9880 = malloc(100)  [call from 0x1eea82d0]
0x1f3f9920 = malloc(32K)  [call from 0x1ecec760]
0x1f401940 = malloc(512)  [call from 0x1ed827e6]
0x1f401b60 = malloc(272)  [call from 0x1ecec8be]
0x1f401ca0 = malloc(272)  [call from 0x1ecec8be]
0x1f401de0 = malloc(272)  [call from 0x1ecec8be]
0x1f401f20 = malloc(272)  [call from 0x1ecec8be]
0x1f402060 = malloc(272)  [call from 0x1ecec8be]
0x1f4021a0 = malloc(272)  [call from 0x1ecec8be]
0x1f4022e0 = malloc(272)  [call from 0x1ecec8be]
0x1f402420 = malloc(272)  [call from 0x1ecec8be]
0x1f402560 = malloc(272)  [call from 0x1ecec8be]
0x1f4026a0 = malloc(272)  [call from 0x1ecec8be]
0x1f4027e0 = malloc(272)  [call from 0x1ecec8be]
0x1f402920 = malloc(272)  [call from 0x1ecec8be]
0x1f402a60 = malloc(272)  [call from 0x1ecec8be]
0x1f402ba0 = malloc(272)  [call from 0x1ecec8be]
0x1f402ce0 = malloc(272)  [call from 0x1ecec8be]
0x1f402e20 = malloc(272)  [call from 0x1ecec8be]
0x1f402f60 = malloc(272)  [call from 0x1ecec8be]
0x1f4030a0 = malloc(272)  [call from 0x1ecec8be]
0x1f4031e0 = malloc(272)  [call from 0x1ecec8be]
0x1f403320 = malloc(272)  [call from 0x1ecec8be]
0x1f403460 = malloc(272)  [call from 0x1ecec8be]
0x1f4035a0 = malloc(272)  [call from 0x1ecec8be]
0x1f4036e0 = malloc(272)  [call from 0x1ecec8be]
0x1f403820 = malloc(272)  [call from 0x1ecec8be]
0x1f403960 = malloc(272)  [call from 0x1ecec8be]
0x1f403aa0 = malloc(272)  [call from 0x1ecec8be]
0x1f403be0 = malloc(272)  [call from 0x1ecec8be]
0x1f403d20 = malloc(272)  [call from 0x1ecec8be]
0x1f403e60 = malloc(272)  [call from 0x1ecec8be]
0x1f403fa0 = malloc(272)  [call from 0x1ecec8be]
0x1f4040e0 = malloc(272)  [call from 0x1ecec8be]
0x1f404220 = malloc(272)  [call from 0x1ecec8be]
0x1f404360 = malloc(272)  [call from 0x1ecec8be]
0x1f4044a0 = malloc(272)  [call from 0x1ecec8be]
0x1f4045e0 = malloc(272)  [call from 0x1ecec8be]
0x1f404720 = malloc(272)  [call from 0x1ecec8be]
0x1f404860 = malloc(272)  [call from 0x1ecec8be]
0x1f4049a0 = malloc(272)  [call from 0x1ecec8be]
0x1f404ae0 = malloc(272)  [call from 0x1ecec8be]
0x1f404c20 = malloc(272)  [call from 0x1ecec8be]
0x1f404d60 = malloc(272)  [call from 0x1ecec8be]
0x1f404ea0 = malloc(272)  [call from 0x1ecec8be]
0x1f404fe0 = malloc(272)  [call from 0x1ecec8be]
0x1f405120 = malloc(272)  [call from 0x1ecec8be]
0x1f405260 = malloc(272)  [call from 0x1ecec8be]
0x1f4053a0 = malloc(272)  [call from 0x1ecec8be]
0x1f4054e0 = malloc(272)  [call from 0x1ecec8be]
0x1f405620 = malloc(272)  [call from 0x1ecec8be]
0x1f405760 = malloc(272)  [call from 0x1ecec8be]
0x1f4058a0 = malloc(272)  [call from 0x1ecec8be]
0x1f4059e0 = malloc(512)  [call from 0x1ec5f5e8]
0x1f405c00 = malloc(16K)  [call from 0x1ec5f61a]
0x1f409c20 = malloc(4.0K) [call from 0x1ec5f676]
0x1f40ac40 = malloc(4.0K) [call from 0x1ed61e7c]
0x1f40bc60 = malloc(4.0K) [call from 0x1ed61ee2]
0x1f40cc80 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40cce0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40cd40 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40cda0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40ce00 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40ce60 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40cec0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40cf20 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40cf80 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40cfe0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40d040 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40d0a0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40d100 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40d160 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40d1c0 = malloc(60)   [GPIOMAN_DEFINE_T]
0x1f40d220 = malloc(8)    [call from 0x1ec81ec0]
0x1f40d260 = malloc(4.0K) [powerman]
0x1f40e280 = malloc(3.0K) [call from 0x1ecbda0a]
0x1f40eea0 = malloc(356K) [call from 0x1ecbda40]
0x1f467ec0 = malloc(356K) [call from 0x1ecbda7a]
0x1f4c0ee0 = malloc(66K)  [call from 0x1ecbdabc]
0x1f4d16c0 = malloc(1.1K) [call from 0x1ee47aa8]
0x1f4d1b40 = malloc(16K)  [call from 0x1ec7a10c]
0x1f4d5b60 = malloc(16K)  [mbox_read]
0x1f4d9b80 = malloc(4.0K) [display_update]
0x1f4daba0 = malloc(4.0K) [temp_check]
0x1f4dbbc0 = malloc(16K)  [vchiq dma_xfer]
0x1f4dfc80 = malloc(16K)  [vchiq dma_xfer]
0x1f4e3d40 = malloc(16K)  [vchiq dma_xfer]
0x1f4e7e00 = malloc(16K)  [vchiq dma_xfer]
0x1f4ebec0 = malloc(8.0K) [VCHIQ-0]
0x1f4edee0 = malloc(8.0K) [VCHIQr-0]
0x1f4eff00 = malloc(8.0K) [VCHIQs-0]
0x1f4f1f20 = malloc(56)   [imageconv stats]
0x1f4f1f80 = malloc(36)   [vchiq_shim]
0x1f4f1fe0 = malloc(256)  [vchiu_queue_init]
0x1f4f2100 = malloc(476)  [VCHIQ service]
0x1f4f2300 = malloc(36)   [vchiq_shim]
0x1f4f2360 = malloc(256)  [vchiu_queue_init]
0x1f4f2480 = malloc(476)  [VCHIQ service]
0x1f4f2680 = malloc(36)   [vchiq_shim]
0x1f4f26e0 = malloc(256)  [vchiu_queue_init]
0x1f4f2800 = malloc(476)  [VCHIQ service]
0x1f4f2a00 = malloc(2.0K) [call from 0x1eea82b4]
0x1f4f3200 = malloc(100)  [call from 0x1eea82d0]
0x1f4f32a0 = malloc(4.0K) [GCMD_V]
0x1f4f42c0 = malloc(2.0K) [HAUDVCHI]
0x1f4f4ae0 = malloc(36)   [vchiq_shim]
0x1f4f4b40 = malloc(256)  [vchiu_queue_init]
0x1f4f4c60 = malloc(476)  [VCHIQ service]
0x1f4f4e60 = malloc(21K)  [ILCS State]
0x1f4fa120 = malloc(256)  [vchiu_queue_init]
0x1f4fa240 = malloc(476)  [VCHIQ service]
0x1f4fa440 = malloc(52)   [ILCS_VC_COMMON]
0x1f4fa4a0 = malloc(4.0K) [ILCS_VC]
0x1f4fb4c0 = malloc(3.0K) [call from 0x1ee5724c]
0x1f4fc0e0 = malloc(36)   [vchiq_shim]
0x1f4fc140 = malloc(256)  [vchiu_queue_init]
0x1f4fc260 = malloc(476)  [VCHIQ service]
0x1f4fc460 = malloc(36)   [vchiq_shim]
0x1f4fc4c0 = malloc(256)  [vchiu_queue_init]
0x1f4fc5e0 = malloc(476)  [VCHIQ service]
0x1f4fc7e0 = malloc(36)   [vchiq_shim]
0x1f4fc840 = malloc(256)  [vchiu_queue_init]
0x1f4fc960 = malloc(476)  [VCHIQ service]
0x1f4fcb60 = malloc(3.0K) [call from 0x1ee57332]
0x1f4fd780 = malloc(36)   [vchiq_shim]
0x1f4fd7e0 = malloc(256)  [vchiu_queue_init]
0x1f4fd900 = malloc(476)  [VCHIQ service]
0x1f4fdb00 = malloc(36)   [vchiq_shim]
0x1f4fdb60 = malloc(256)  [vchiu_queue_init]
0x1f4fdc80 = malloc(476)  [VCHIQ service]
0x1f4fde80 = malloc(36)   [vchiq_shim]
0x1f4fdee0 = malloc(256)  [vchiu_queue_init]
0x1f4fe000 = malloc(476)  [VCHIQ service]
0x1f4fe200 = malloc(60)   [call from 0x1eda0378]
0x1f4fe260 = malloc(16K)  [vchiu_queue_init]
0x1f502280 = malloc(476)  [VCHIQ service]
0x1f502480 = malloc(60)   [call from 0x1eda0378]
0x1f5024e0 = malloc(16K)  [vchiu_queue_init]
0x1f506500 = malloc(476)  [VCHIQ service]
0x1f506700 = malloc(60)   [call from 0x1eda0378]
0x1f506760 = malloc(16K)  [vchiu_queue_init]
0x1f50a780 = malloc(476)  [VCHIQ service]
0x1f50a980 = malloc(476)  [VCHIQ service]
0x1f50ab80 = malloc(320K) [KHRN_S]
0x1f55aba0 = malloc(36)   [vchiq_shim]
0x1f55ac00 = malloc(256)  [vchiu_queue_init]
0x1f55ad20 = malloc(476)  [VCHIQ service]
0x1f55af20 = malloc(4.0K) [HREQ task]
0x1f55bf40 = malloc(4.6K) [call from 0x1ee574e0]
0x1f55d1c0 = malloc(4.0K) [FILESERV]
0x1f55e1e0 = malloc(36)   [vchiq_shim]
0x1f55e240 = malloc(256)  [vchiu_queue_init]
0x1f55e360 = malloc(476)  [VCHIQ service]
0x1f55e560 = malloc(608)  [Shared Memory Service]
0x1f55e7e0 = malloc(4.0K) [sm_thread]
0x1f55f800 = malloc(36)   [vchiq_shim]
0x1f55f860 = malloc(256)  [vchiu_queue_init]
0x1f55f980 = malloc(476)  [VCHIQ service]
0x1f55fb80 = malloc(488)  [Shared Memory Cache Test]
0x1f55fda0 = malloc(4.0K) [smct_thread]
0x1f560dc0 = malloc(36)   [vchiq_shim]
0x1f560e20 = malloc(256)  [vchiu_queue_init]
0x1f560f40 = malloc(476)  [VCHIQ service]
0x1f561140 = malloc(1.3K) [CEA modes table]
0x1f561680 = malloc(1.7K) [DMT modes table]
0x1f561d80 = malloc(4.0K) [call from 0x1ee588fe]
0x1f562da0 = malloc(36)   [vchiq_shim]
0x1f562e00 = malloc(256)  [vchiu_queue_init]
0x1f562f20 = malloc(476)  [VCHIQ service]
0x1f563120 = malloc(36)   [vchiq_shim]
0x1f563180 = malloc(256)  [vchiu_queue_init]
0x1f5632a0 = malloc(476)  [VCHIQ service]
0x1f5634a0 = malloc(36)   [vchiq_shim]
0x1f563500 = malloc(256)  [vchiu_queue_init]
0x1f563620 = malloc(476)  [VCHIQ service]
0x1f563820 = malloc(4.0K) [call from 0x1ee58a16]
0x1f564840 = malloc(36)   [vchiq_shim]
0x1f5648a0 = malloc(256)  [vchiu_queue_init]
0x1f5649c0 = malloc(476)  [VCHIQ service]
0x1f564bc0 = malloc(36)   [vchiq_shim]
0x1f564c20 = malloc(256)  [vchiu_queue_init]
0x1f564d40 = malloc(476)  [VCHIQ service]
0x1f564f40 = malloc(36)   [vchiq_shim]
0x1f564fa0 = malloc(256)  [vchiu_queue_init]
0x1f5650c0 = malloc(476)  [VCHIQ service]
0x1f5652c0 = malloc(4.0K) []
0x1f5662e0 = malloc(36)   [vchiq_shim]
0x1f566340 = malloc(256)  [vchiu_queue_init]
0x1f566460 = malloc(476)  [VCHIQ service]
0x1f566660 = malloc(36)   [vchiq_shim]
0x1f5666c0 = malloc(256)  [vchiu_queue_init]
0x1f5667e0 = malloc(476)  [VCHIQ service]
0x1f5669e0 = malloc(36)   [vchiq_shim]
0x1f566a40 = malloc(256)  [vchiu_queue_init]
0x1f566b60 = malloc(476)  [VCHIQ service]
0x1f566d60 = malloc(4.0K) []
0x1f567d80 = malloc(36)   [vchiq_shim]
0x1f567de0 = malloc(256)  [vchiu_queue_init]
0x1f567f00 = malloc(476)  [VCHIQ service]
0x1f568100 = malloc(36)   [vchiq_shim]
0x1f568160 = malloc(256)  [vchiu_queue_init]
0x1f568280 = malloc(476)  [VCHIQ service]
0x1f568480 = malloc(36)   [vchiq_shim]
0x1f5684e0 = malloc(256)  [vchiu_queue_init]
0x1f568600 = malloc(476)  [VCHIQ service]
0x1f568800 = malloc(36)   [vchiq_shim]
0x1f568860 = malloc(256)  [vchiu_queue_init]
0x1f568980 = malloc(476)  [VCHIQ service]
0x1f568b80 = malloc(36)   [vchiq_shim]
0x1f568be0 = malloc(256)  [vchiu_queue_init]
0x1f568d00 = malloc(476)  [VCHIQ service]
0x1f568f00 = malloc(36)   [vchiq_shim]
0x1f568f60 = malloc(256)  [vchiu_queue_init]
0x1f569080 = malloc(476)  [VCHIQ service]
0x1f569280 = malloc(36)   [vchiq_shim]
0x1f5692e0 = malloc(256)  [vchiu_queue_init]
0x1f569400 = malloc(476)  [VCHIQ service]
0x1f569600 = malloc(36)   [vchiq_shim]
0x1f569660 = malloc(256)  [vchiu_queue_init]
0x1f569780 = malloc(476)  [VCHIQ service]
0x1f569980 = malloc(36)   [vchiq_shim]
0x1f5699e0 = malloc(256)  [vchiu_queue_init]
0x1f569b00 = malloc(476)  [VCHIQ service]
0x1f569d00 = malloc(36)   [vchiq_shim]
0x1f569d60 = malloc(256)  [vchiu_queue_init]
0x1f569e80 = malloc(476)  [VCHIQ service]
0x1f56a080 = malloc(36)   [vchiq_shim]
0x1f56a0e0 = malloc(256)  [vchiu_queue_init]
0x1f56a200 = malloc(476)  [VCHIQ service]
0x1f56a400 = malloc(476)  [VCHIQ service]
0x1f56a600 = malloc(476)  [VCHIQ service]
0x1f56a800 = malloc(476)  [VCHIQ service]
0x1f56aa00 = malloc(476)  [VCHIQ service]
0x1f56ac00 = malloc(476)  [VCHIQ service]
0x1f56ae00 = malloc(476)  [VCHIQ service]
0x1f56b000 = malloc(476)  [VCHIQ service]
0x1f56b200 = malloc(476)  [VCHIQ service]
0x1f56b400 = malloc(476)  [VCHIQ service]
0x1f56b600 = malloc(476)  [VCHIQ service]
0x1f56b800 = malloc(4.3K) [mmal debug log]
0x1f56c940 = malloc(16K)  [mmal_host_log]
0x1f570980 = malloc(512)  [vchiu_queue_init]
0x1f570ba0 = malloc(476)  [VCHIQ service]
0x1f570da0 = malloc(40)   [call from 0x1edb6632]
0x1f570e00 = malloc(40)   [call from 0x1edb6632]
0x1f570e60 = malloc(40)   [call from 0x1edb6632]
0x1f570ec0 = malloc(40)   [call from 0x1edb6632]
0x1f570f20 = malloc(40)   [call from 0x1edb6632]
0x1f570f80 = malloc(40)   [call from 0x1edb6632]
0x1f570fe0 = malloc(40)   [call from 0x1edb6632]
0x1f571040 = malloc(40)   [call from 0x1edb6632]
0x1f5710a0 = malloc(40)   [call from 0x1edb6632]
0x1f571100 = malloc(40)   [call from 0x1edb6632]
0x1f571160 = malloc(40)   [call from 0x1edb6632]
0x1f5711c0 = malloc(40)   [call from 0x1edb6632]
0x1f571220 = malloc(40)   [call from 0x1edb6632]
0x1f571280 = malloc(40)   [call from 0x1edb6632]
0x1f5712e0 = malloc(40)   [call from 0x1edb6632]
0x1f571340 = malloc(40)   [call from 0x1edb6632]
0x1f5713a0 = malloc(40)   [call from 0x1edb6632]
0x1f571400 = malloc(40)   [call from 0x1edb6632]
0x1f571460 = malloc(40)   [call from 0x1edb6632]
0x1f5714c0 = malloc(40)   [call from 0x1edb6632]
0x1f571520 = malloc(40)   [call from 0x1edb6632]
0x1f571580 = malloc(256)  [mmal msg queue mem]
0x1f5716a0 = malloc(4.0K) [mmal msg queue ]
0x1f5726c0 = malloc(4.0K) [mmal msg queue ]
0x1f5736e0 = malloc(4.0K) [mmal worker]
0x1f574700 = malloc(476)  [VCHIQ service]
0x1f574900 = malloc(4.0K) [vc watchdog]
0x1f575920 = malloc(1.0K) [call from 0x1ede9cec]
0x1f575d40 = malloc(128K) [call from 0x1ede9d92]
0x1f595d50 = hole(9.9M)
Malloced:1.9M Remaining:9.9M
citiq commented 9 years ago

After weekend I have found the same RTOS ThreadX error in log on another RPi (with GPU frozen), but the timestamp from Friday is greater than the most recent timestamp. 

$ sudo /opt/vc/bin/vcdbg log assert
000941.552: assert( (open->periph_setup->port == I2C_PORT_0 && (open->periph_setup->sda_pin == 0 || open->periph_setup->sda_pin == 28) && (open->periph_setup->scl_pin == 1 || open->periph_setup->scl_pin == 29)) || (open->periph_setup->port == I2C_PORT_1 && (open->periph_setup->sda_pin == 2 && open->periph_setup->scl_pin == 3)) || open->periph_setup->port == I2C_PORT_2 ) failed; ../../../../../vcfw/drivers/chip/vciv/2708/i2c.c::i2c_open line 444
604978.235: assert( new_display_num != 0xff ) failed; ../../../../../middleware/dispmanx/dispmanx.c::dispmanx_display_open line 4202
604978.287: assert( s == 0 ) failed; ../../../../../helpers/arm_loader/arm_display.c::arm_display_set line 1085
604978.338: assert( s == 0 ) failed; ../../../../../helpers/arm_loader/arm_loader.c::handle_mbox_property line 2177
628535.496: assert( (interrupt_save & (1<<30)) || ((int)_tx_thread_system_state < 0) ) failed; ../../../../../vcfw/rtos/threadx/rtos_threadx_latch.c::rtos_latch_get_real line 99

Are the timestamps in log somehow related to the current time or uptime?

pelwell commented 9 years ago

The timestamps are a misinterpretation of values captured from the system timer. Move the decimal point three places to the left to get more sensible timestamps, e.g. 000.941552: assert...

The assert is warning about a coding error; the calling thread is waiting for a latch (mutex) with interrupts disabled, which will deadlock if the mutex is currently claimed by something running on the current core.

citiq commented 9 years ago

@pelwell That coding error is in firmware?

pelwell commented 9 years ago

Yes, it is. Unfortunately the assert logging doesn't include a call stack, otherwise it would be trivial to find (but not necessary to fix).

popcornmix commented 9 years ago

The problem is the rtos_latch_get_real function is called all the time - probably hundreds of times a second when the GPU is doing stuff, so assert in the log doesn't narrow it down much.

If you can provide instructions to reproduce this, then we can leave it running with a debugger connected overnight, and we'll get the call stack. E.g. if you say, "start with clean raspbian image, run this script, wait 12 hours", then I suspect we'll be able to fix it.

However it is not something I've seen (and have had code running with debugger attached for probably thousands of hours), so it may not be something we'll just run into by chance.

citiq commented 9 years ago

Aha, as the current system image is quite far from being clean raspbian, I still have no suspect packages, nor exact steps. Could be the call stack determined from a full memory dump? I can send or upload 0,5GiB output of vcdbg save run on 4 devices with a hang.

pelwell commented 9 years ago

No, the call stack isn't recorded. Provided we can agree on a firmware revision, a script to run after a reboot would probably suffice. It's certainly worth a try.

fkokai commented 9 years ago

Hi Guys,

Is there any progress? I've a version 2 Pi, no overclocking, 64MB GPU mem, firmware version Jun 10 2015 20:42:58 Copyright (c) 2012 Broadcom version a0f9db571a2bb980469502bd4de2c9793b3223c4 (clean) (release)

And the issue definitely comes from time to time. Unfortunately I was unable to find any correlation with anything. I face the problem when I try to read system temperature, but if I understand it right, it is a symptom, not a cause.

Can I help you with any further information?

Ferenc

popcornmix commented 9 years ago

We really need instructions for how to reproduce the issue. Without that it's unlikely to be fixed.

fkokai commented 9 years ago

I got these uncomfortable hangs on a production pi, I have no way to experiment on it, but I'm going to set up an another one with as identical software as possible. Will see...

By the way, I experience it with minibian, if it does matter... Don't know. Thought to share...

fkokai commented 9 years ago

Made some stats. The longest period without the issue was about 15 days, the shortest one is just about one and a half. The pi is intentionally always on with some negligible exceptions. Doesn't seem an easy-to-catch one...

Ruffio commented 9 years ago

@fkokai can you describe a way to reproduce it?

fkokai commented 9 years ago

Unfortunately I don't know a deterministic way to reproduce it :(

I have a node.js application which reads /sys/class/thermal/thermal_zone0/temp every 2 minutes. After some time the node.js task hangs, load rises to ~8. Process goes to D state. After kill it becomes a zombie. In this state cat /sys/class/thermal/thermal_zone0/temp and vcgencmd measure_temp commands also hang. Reboot is not possible, the only solution is to powercycle.

I'll check if it occurs with a simple shell script which reads (and maybe logs) temperature, without all the other ornaments and let it run for a while...

popcornmix commented 9 years ago

Can you change you node.js to read temp every 2 seconds for example? It would be interesting to find out if the failure occurs much more rapidly (as it would if reading the temperature is causing the crash), or if it still takes the usual time (which would suggest the temp failing is just a symptom of some unrelated hang of the GPU).

fkokai commented 9 years ago

Yes, definitely, but only on a different Pi. Maybe I would omit all the nodejs stuff and do it only with a shell script first. Nice evening project ;)

fkokai commented 9 years ago

Actually I'm about 250kms away from the problematic one, and a simple powercycle is not so simple as it seems :) This is why I'm going to do it on an other Pi. Eventually if you have a Pi lying around it may worth trying to run a so simple test like this: watch -d -n 2 "cat /sys/class/thermal/thermal_zone0/temp"

fkokai commented 9 years ago

Hi all,

just to inform you, I started a test on a separate pi yesterday evening. It runs the watch command mentioned in my previous post. No issues yet. I keep it running...

I removed the temperature sensor from the other nodejs app, it runs stable since then, no hangs, but only a day has elapsed since that and I've experienced as long stable periods as this before, so it doesn's show too much.

popcornmix commented 9 years ago

I've left: while :; do cat /sys/class/thermal/thermal_zone0/temp; done running over the last couple of nights with gpu debugger attached and it's still running without errors in the morning.

fkokai commented 9 years ago

It seems that reading the temp alone is not enough. My Pi doing the watch is stable too. It's a B+, I faced the problem on a Pi2. It may be one difference.

But the other one (which I had the problem with before) runs rock solid since eliminating the temperature read, so there must be something correlated... Maybe some resource contention or I don't know. Groping in the dark :\