task kworker :Workqueue: events_freezable mmc_rescan blocked occurs midnightly
Nobody has claimed this yet.
Assessment
- Difficulty
- 5/5
- Estimated time
- Over a week
- Newbie friendliness
- 20/100
- Issue type
- Bug
- Clarity
- Needs clarification
- Activity status
- Stale
- Tech stack
- c, linux
- Domain
- embedded-iot, operating-systems, performance
Research direction
Start with the reported kernel stack trace at the mmc_rescan workqueue entry, especially __mmc_claim_host and mmc_sd_detect, and compare it with the surrounding Raspberry Pi kernel behavior. Reproduce or correlate the daily failures using the provided kernel, InfluxDB, systemd, and memory logs; done requires identifying a kernel-related cause and confirming that the recurring hang and memory failures no longer occur.
Written by the indexing model from the issue text.
Description
RuuviCollector inserts frequently and continuously into influxdb.
influxdb logs: POST /write ing logging every 5 seconds until
00:10:22
RuuviCollector reports
...12:10:36 AM org.influxdb.impl.BatchProcessor write
...SEVERE: Batch could not be sent. Data will be lost
...org.influxdb.InfluxDBIOException: java.net.SocketTimeoutException: timeout
... ... many java trace messages follow slowly 1 every second +/-
00:12:32 influxdb reports 5 additional POST /writes until
00:12:39 fatal error: runtime: out of memory,
00:12:41 runtime stack:,
00:12:48 runtime.throw(0xbe8b5d, 0x16)
00:12:51 ...panic.go:608 +0x5c, em_linux.go:156 +0xac, malloc.go:1230 +0x94,
malloc.go:525 +0x54, mheap.go:920 +0x2c, ... mcentral.go:232 +0x94, ...
asm_arm.s:354 +0x84, proc.go:1229...
00:12:52 runtime.systemstack_switch()...
00:12:52 RuuviCollector reports ...SEVERE: Batch could not be sent.... again
influxdb continues with stack_switch, runtime.goexit(), main.main()
goroutine 5 [syscall, 7383 minutes]: (sic)
more,more
00:12:53 systemd[1]: Stopping RuuviCollector...
more,more
systemd[1]: ruuvicollector.service: Main process exited, code=exited, status=15/n/a
last messages for influxdb (for a while!)
00:12:53
go/src/github.com/influxdata/influxdb/tsdb/engine/tsm1/engine.go:499 +0x40
created by github.com/influxdata/influxdb/tsdb/engine/tsm1.(*Engine).enableSnapshotCompactions
go/src/github.com/influxdata/influxdb/tsdb/engine/tsm1/engine.go:499 +0xfc
systemd starts RuuviCollector immediately (even though RestartSec=300)
00:13:01(vmstat 5 2 | logger -p kern.notice )
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 3 0 290356 4640 75312 0 0 45 19 54 78 18 1 80 0 0 1 0 0 278452 4640 77488 0 0 435 0 252 306 98 2 0 0 0
00:15:13 suddenly influx fatal error: runtime: out of memory (no other messages since 00:12:53 !!)
influxdb crying continues
00:15:15 systemd Stopping RuuviCollector...
00:15:15 systemd[1]: Stopped InfluxDB
influxdb crying continues
00:15:16 last message from influxdb:
created by net/http.setRequestCancel
client.go:320 +0x210
00:15:47 kern.err kernel: [529613.883893] INFO: task kworker/0:1:10051 blocked for more than 120 seconds.
00:15:47 kern.err kernel: [529613.883917] Tainted: G C 4.14.98+ # 1200
00:15:47 kern.err kernel: [529613.883923] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
00:15:48 kern.info kernel: [529613.883933] kworker/0:1 D 0 10051 2 0x00000000
00:15:48 kern.info kernel: [529613.883976] Workqueue: events_freezable mmc_rescan
00:15:49 kern.warning kernel: [529613.884035] [<c064e450>] (__schedule) from [[<c064e910>] (schedule+0x50/0xa8)
00:15:50 kern.warning kernel: [529613.884060] [<c064e910>] (schedule) from [<c04cfb58>] (__mmc_claim_host+0x98/0x210)
00:15:50 kern.warning kernel: [529613.884079] [<c04cfb58>] (__mmc_claim_host) from [<c04cfd00>] (mmc_get_card+0x30/0x34)
00:15:51 kern.warning kernel: [529613.884106] [<c04cfd00>] (mmc_get_card) from [<c04d8c9c>] (mmc_sd_detect+0x20/0x70)
00:15:51 kern.warning kernel: [529613.884126] [<c04d8c9c>] (mmc_sd_detect) from [<c04d28a8>] (mmc_rescan+0x288/0x490)
00:15:52 kern.warning kernel: [529613.884153] [<c04d28a8>] (mmc_rescan) from [<c00393b4>] (process_one_work+0x11c/0x398)
00:15:52 kern.warning kernel: [529613.884174] [<c00393b4>] (process_one_work) from [<c003966c>] (worker_thread+0x3c/0x544)
00:15:52 kern.warning kernel: [529613.884200] [<c003966c>] (worker_thread) from [<c003f568>] (kthread+0x120/0x15c)
00:15:53 kern.warning kernel: [529613.884232] [<c003f568>] (kthread) from [<c000fe2c>] (ret_from_fork+0x14/0x28)
00:17:02 cronjob select from influxdb fails (no word from influxdb)
00:19:08 fatal error: runtime: out of memory, and crying...
After
00:19:10 systemd starts influxdb again
00:21:34 fatal error: runtime: out of memory, and crying...
00:21:36 start,
00:37:52 influxdb reports POST /write and happily continues reporting every 5 seconds
select last occurs at 07,17,27,37,47,57
chronograf starts a session at 10:30:07
writes continue every 5 seconds
Things I find interesting :
At first sign of a problem influxdb writes log messages very slowly then blasts out all the details
7383 minutes is 123 hours I don't think so!
Additional information:
System is a raspberry pi zero W, connected to network via wifi.
Linux pi93graf 4.14.98+ # 1200 Tue Feb 12 20:11:02 GMT 2019 armv6l GNU/Linux
InfluxDB v1.7.4 (git: 1.7 ef77e72)
influxdb config (none comments)
+++
wal-fsync-delay = "5s"
trace-logging-enabled = false
query-log-enabled = false
cache-max-memory-size = "300m"
series-id-set-cache-size = 100
query-timeout = "90s"
log-queries-after = "10s"
level = "warn"
+++
vm.swappiness = 10
vm.dirty_background_ratio = 5
vm.dirty_ratio = 80
I changed vm.swappiness to 5 no help.
root is ext4 noatime
swap is a partition
influxdb is on f2fs
+++
Complete log is at http://MyBeacons.info/influx-memoryfail2.log.gz
A weeks worth of atsar is available if anyone thinks that would be useful.
Yesterday copied system to a SanDisk Extreme Plus SD card ( dd writes zeros 3 times faster) most recent occurrence just after noon ! 12:48:08
This happens (nearly)daily between 00:10 and 00:30 and occasionally at random times.
Any and all comments, requests for additional info, suggestions are appreciated.
- Dominant language
- C
- Stars
- 13.2k
- Forks
- 5.5k
- Avg merge
- 2d 21h
- Merged PRs (30d)
- 21
Contributor guide
No contributing guide indexed for this repository
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
More from raspberrypi/linux
-
Difficulty 2/5 1-3 hours Newbie friendliness 68/100
raspberrypi/linux#7415 · 2 comments · 1 reaction ·
-
rp1-cfe doesn't forward V4L2_EVENT_SOURCE_CHANGE event from csi-2 sensor driver to userspace app Open
Difficulty 2/5 1-3 hours Newbie friendliness 72/100
raspberrypi/linux#7399 · 1 comment ·
-
Difficulty 1/5 Under an hour Newbie friendliness 82/100
raspberrypi/linux#7357 · 1 comment ·
-
Difficulty 2/5 1-3 hours Newbie friendliness 68/100
raspberrypi/linux#7054 · 2 comments ·
-
Difficulty 4/5 3-5 days Newbie friendliness 48/100
raspberrypi/linux#7634 · 8 comments · 1 reaction ·
All issues in raspberrypi/linux
Similar issues
-
Difficulty 2/5 1-3 hours Newbie friendliness 88/100
zephyrproject-rtos/zephyr#119726 ·
-
[Bounty proposal] fix(web): memory insights count an evening memory on the next day ($25 proposed) Open
Difficulty 2/5 1-3 hours Newbie friendliness 84/100
BasedHardware/omi#15320 ·
-
[adam] AdamNet network read doesn't cap to MAX_ADAM_PACKET_LEN, overflows client receive buffers Open
Difficulty 2/5 1-3 hours Newbie friendliness 88/100
FujiNetWIFI/fujinet-firmware#1649 · 2 comments ·
-
Difficulty 2/5 1-3 hours Newbie friendliness 68/100
HarbourMasters/Shipwright#7229 ·
-
Difficulty 2/5 1-3 hours Newbie friendliness 72/100
riscv-software-src/riscv-isa-sim#2435 · 1 comment ·