task kworker :Workqueue: events_freezable mmc_rescan blocked occurs midnightly

Open
#2,980 4 comments 0 reactions 0 assignees View on GitHub

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

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

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

More from raspberrypi/linux

All issues in raspberrypi/linux

Similar issues

More C issues

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.