rpi2 hangup during poudriere build: lots of pfault wmseg status

From: Mark Millard <markmi_at_dsl-only.net>
Date: Tue, 5 Dec 2017 21:57:56 -0800
I tried to build some ports on a rpi2
(via poudriere) but it hung up:
Ethernet and normal console use. (Note:
the root file system is on a USB SSD
and the swap partition is also on that
USB SSD.)

But ~^b worked for getting to the db>
prompt on the console.

From there a ps suggests that it got hung
up in pfault activity. (Possibly insufficient
RAM+swap-partition space?) But it is not
clear to me that it should end up hung up
vs. killing processes or other such.

db> ps
  pid  ppid  pgrp   uid  state   wmesg   wchan       cmd
36369 36770 36588     0  D+      pfault  0xc0832880  sh
36368 36770 36588     0  D+      pfault  0xc0832880  awk
36367 36770 36588     0  D+      pfault  0xc0832880  awk
36353 88873 36588     0  D+J     pfault  0xc0832880  gmake
35115 35107 36588     0  D+J     pfault  0xc0832880  ld
35107 76552 36588     0  SW+J    wait    0xc4a52398  c++
35071 35066 36588     0  D+J     pfault  0xc0832880  ld
35066 76552 36588     0  SW+J    wait    0xc64d6730  c++
35047 35036 36588     0  D+J     pfault  0xc0832880  ld
35036 76552 36588     0  SW+J    wait    0xc5efc000  c++
88873 88868 36588     0  S+J     select  0xc5ea0b24  gmake
88868 88867 36588     0  SW+J    wait    0xc3da1ac8  sh
88867 88674 36588     0  SW+J    wait    0xc5904398  gmake
88674 28839 36588     0  SW+J    wait    0xc66e4730  gmake
76552 76450 36588     0  SW+J    wait    0xc5eb5ac8  gmake
76450 76438 36588     0  SW+J    wait    0xc3aa2730  sh
76438 76380 36588     0  SW+J    wait    0xc64d6000  gmake
76380 28839 36588     0  SW+J    wait    0xc66e4ac8  gmake
28839 28828 36588     0  SW+J    wait    0xc5f78ac8  gmake
28828 28826 36588     0  SW+J    wait    0xc4a52000  sh
28826 28825 36588     0  SW+J    wait    0xc5eb5398  gmake
28825 28793 36588     0  SW+J    wait    0xc5c5d730  sh
28793 28792 36588     0  SW+J    wait    0xc4262ac8  make
28792 23997 36588     0  SW+     wait    0xc56fb000  sh
23997 36588 36588     0  D+      pfault  0xc0832880  sh
40786 36588 36588     0  S+      piperd  0xc422c5b8  sh
36770 36588 36588     0  S+      wait    0xc5f78000  sh
36588   748 36588     0  D+      pfault  0xc0832880  sh
36387   748 36387     0  TW+                         vi
  748   747   748     0  SW+     wait    0xc4205000  sh
  747   741   747  1001  SW+     wait    0xc4261398  su
  741   740   741  1001  SWs+    wait    0xc3da0000  sh
  740   737   737  1001  S       select  0xc4227524  sshd
  737   670   737     0  Ss      select  0xc42275a4  sshd
  723   722   723     0  D+      pfault  0xc0832880  sh
  722     1   722     0  SWs+    wait    0xc4260398  login
  721     1   721     0  Ss+     ttyin   0xc39d9474  getty
  674     1   674     0  ?Ws                         cron
  670     1   670     0  Ds      pfault  0xc0832880  sshd
  639     1   639     0  Ss      select  0xc4227724  powerd
  636     1   636     0  Ss      (threaded)          ntpd
100106                   S       select  0xc4227764  ntpd
  588   587   587     0  S       (threaded)          nfsd
100098                   S       rpcsvc  0xc42ecc50  nfsd: master
100110                   S       rpcsvc  0xc3995250  nfsd: service
100111                   S       rpcsvc  0xc41721d0  nfsd: service
100112                   S       rpcsvc  0xc4171d50  nfsd: service
100113                   S       rpcsvc  0xc39952d0  nfsd: service
100114                   S       rpcsvc  0xc41725d0  nfsd: service
100115                   S       rpcsvc  0xc4171dd0  nfsd: service
100116                   S       rpcsvc  0xc39956d0  nfsd: service
100117                   S       rpcsvc  0xc3995350  nfsd: service
100118                   S       rpcsvc  0xc4172550  nfsd: service
100119                   S       rpcsvc  0xc3995750  nfsd: service
100120                   S       rpcsvc  0xc41726d0  nfsd: service
100121                   S       rpcsvc  0xc39953d0  nfsd: service
100122                   S       rpcsvc  0xc4172650  nfsd: service
100123                   S       rpcsvc  0xc41723d0  nfsd: service
100124                   S       rpcsvc  0xc4172450  nfsd: service
100125                   S       rpcsvc  0xc3995450  nfsd: service
100126                   S       rpcsvc  0xc4171cd0  nfsd: service
100127                   S       rpcsvc  0xc4172350  nfsd: service
100128                   S       rpcsvc  0xc41724d0  nfsd: service
100129                   S       rpcsvc  0xc39954d0  nfsd: service
100130                   S       rpcsvc  0xc4172250  nfsd: service
100131                   S       rpcsvc  0xc41720d0  nfsd: service
100132                   S       rpcsvc  0xc41722d0  nfsd: service
100133                   S       rpcsvc  0xc3995550  nfsd: service
100134                   S       rpcsvc  0xc4172050  nfsd: service
100135                   S       rpcsvc  0xc4171e50  nfsd: service
100136                   S       rpcsvc  0xc4172150  nfsd: service
100137                   S       rpcsvc  0xc39955d0  nfsd: service
100138                   S       rpcsvc  0xc4171f50  nfsd: service
100139                   S       rpcsvc  0xc4171ed0  nfsd: service
100140                   S       rpcsvc  0xc3995650  nfsd: service
  587     1   587     0  Ss      select  0xc42277a4  nfsd
  585     1   585     0  Ss      select  0xc4227624  mountd
  455     1   455     0  Ss      select  0xc4103d64  rpcbind
  446     1   446     0  Ds      pfault  0xc0832880  syslogd
  375     1   375     0  Ss      select  0xc4103fa4  devd
  374     1   374    65  Ds      pfault  0xc0832880  dhclient
  328     1   328     0  Ss      select  0xc4227f64  dhclient
  325     1   325     0  Ss      select  0xc3dec4e4  dhclient
   31     0     0     0  DL      vlruwt  0xc3da0730  [vnlru]
   30     0     0     0  DL      syncer  0xc095a6dc  [syncer]
   29     0     0     0  DL      -       0xc095a0c8  [bufspacedaemon]
   28     0     0     0  DL      (threaded)          [bufdaemon]
100070                   D       psleep  0xc0959fc0  [bufdaemon]
100092                   D       sdflush 0xc42ae884  [/ worker]
   27     0     0     0  DL      psleep  0xc095ecb4  [vmdaemon]
   26     0     0     0  RL      (threaded)          [pagedaemon]
100068                   RunQ                        [pagedaemon]
100074                   D       launds  0xc095ebb4  [laundry: dom0]
100075                   D       umarcl  0xc095e8fc  [uma]
   25     0     0     0  SL      worker_ 0xc3757a90  [bcm2835_audio_worke]
   24     0     0     0  SL      VCHI co 0xc3a9980c  [VCHIQka-0]
   23     0     0     0  DL      mmcsd d 0xc3fe4800  [mmcsd0boot1: mmc/sd]
   22     0     0     0  DL      mmcsd d 0xc3fe4a00  [mmcsd0boot0: mmc/sd]
   21     0     0     0  DL      mmcsd d 0xc3fe4c00  [mmcsd0: mmc/sd card]
   20     0     0     0  DL      -       0xc0959c34  [soaiod4]
   19     0     0     0  DL      -       0xc0959c34  [soaiod3]
   18     0     0     0  DL      -       0xc0959c34  [soaiod2]
   17     0     0     0  DL      -       0xc0959c34  [soaiod1]
   16     0     0     0  DL      -       0xc0841298  [rand_harvestq]
   15     0     0     0  DL      waiting 0xc0968ef0  [sctp_iterator]
   14     0     0     0  DL      (threaded)          [usb]
100049                   D       -       0xc3a9f02c  [usbus0]
100050                   D       -       0xc3a9f05c  [usbus0]
100051                   D       -       0xc3a9f08c  [usbus0]
100052                   D       -       0xc3a9f0bc  [usbus0]
100053                   D       -       0xc3a9f0ec  [usbus0]
100067                   D       -       0xc3a5d428  [smsc0]
   13     0     0     0  SL      sema cv 0xc0980d80  [VCHIQs-0]
    9     0     0     0  SL      sema cv 0xc0980d5c  [VCHIQr-0]
    8     0     0     0  SL      sema cv 0xc0980d38  [VCHIQ-0]
    7     0     0     0  DL      (threaded)          [cam]
100031                   D       -       0xc083e140  [doneq0]
100057                   D       -       0xc083e06c  [scanner]
    6     0     0     0  DL      crypto_ 0xc39b50c4  [crypto returns 3]
    5     0     0     0  DL      crypto_ 0xc39b508c  [crypto returns 2]
    4     0     0     0  DL      crypto_ 0xc39b5054  [crypto returns 1]
    3     0     0     0  DL      crypto_ 0xc39b501c  [crypto returns 0]
    2     0     0     0  DL      crypto_ 0xc095e23c  [crypto]
   12     0     0     0  DL      (threaded)          [geom]
100018                   D       -       0xc0967758  [g_event]
100019                   D       -       0xc096775c  [g_up]
100020                   D       -       0xc0967760  [g_down]
   11     0     0     0  WL      (threaded)          [intr]
100006                   I                           [swi6: Giant taskq]
100009                   I                           [swi5: fast taskq]
100011                   I                           [swi6: task queue]
100012                   I                           [swi4: clock (0)]
100013                   I                           [swi4: clock (1)]
100014                   I                           [swi4: clock (2)]
100015                   I                           [swi4: clock (3)]
100016                   I                           [swi3: vm]
100017                   I                           [swi1: netisr 0]
100032                   I                           [intc0,69: bcmrng0]
100033                   I                           [intc0,61: iichb0+]
100034                   I                           [intc0,62: spi0]
100035                   I                           [intc0,28: bcm_dma0]
100036                   I                           [intc0,29: bcm_dma0]
100037                   I                           [intc0,32: bcm_dma0]
100038                   I                           [intc0,33: bcm_dma0]
100039                   I                           [intc0,34: bcm_dma0]
100040                   I                           [intc0,35: bcm_dma0]
100041                   I                           [intc0,1: mbox0]
100042                   I                           [intc0,70: +]
100043                   I                           [swi0: uart]
100044                   I                           [intc0,2: vchiq0]
100048                   I                           [intc0,17: +]
   10     0     0     0  RL      (threaded)          [idle]
100002                   Run     CPU 0               [idle: cpu0]
100003                   Run     CPU 1               [idle: cpu1]
100004                   CanRun                      [idle: cpu2]
100005                   Run     CPU 3               [idle: cpu3]
    1     0     1     0  SLs     wait    0xc38b5000  [init]
    0     0     0     0  RLs     (threaded)          [kernel]
100000                   D       vmwait  0xc0832880  [swapper]
100007                   D       -       0xc38ada00  [thread taskq]
100008                   D       -       0xc38ad980  [aiod_kick taskq]
100010                   D       -       0xc38ad880  [kqueue_ctx taskq]
100021                   D       -       0xc38ad780  [firmware taskq]
100022                   D       -       0xc38ad700  [crypto_0]
100023                   D       -       0xc38ad700  [crypto_1]
100024                   D       -       0xc38ad700  [crypto_2]
100025                   D       -       0xc38ad700  [crypto_3]
100056                   D       -       0xc38ad680  [CAM taskq]
100076                   D       -       0xc3fa1f00  [if_config_tqg_0]
100077                   D       -       0xc40c4100  [softirq_0]
100078                   D       -       0xc40c4080  [softirq_1]
100079                   RunQ                        [softirq_2]
100080                   D       -       0xc40c3f00  [softirq_3]
100081                   D       -       0xc3fa1e00  [if_io_tqg_0]
100082                   D       -       0xc3fa1d80  [if_io_tqg_1]
100083                   RunQ                        [if_io_tqg_2]
100084                   D       -       0xc3fa1c80  [if_io_tqg_3]

Exploring some commands. . .

db> show pageq
pq_free 599
dom 0 page_cnt 205724 free 599 pq_act 160929 pq_inact 3178 pq_laund 0 pq_unsw 0
db> show page
vm_cnt.v_free_count: 599
vm_cnt.v_inactive_count: 3178
vm_cnt.v_active_count: 160929
vm_cnt.v_laundry_count: 0
vm_cnt.v_wire_count: 41018
vm_cnt.v_free_reserved: 333
vm_cnt.v_free_min: 1360
vm_cnt.v_free_target: 4441
vm_cnt.v_inactive_target: 6661
db> show freepages
DOMAIN: 0
FREE LIST 0:

  ORDER (SIZE)  |  NUMBER
                |  POOL 0
--            -- --      --
  08 (001024K)  |  000000
  07 (000512K)  |  000000
  06 (000256K)  |  000000
  05 (000128K)  |  000002
  04 (000064K)  |  000000
  03 (000032K)  |  000000
  02 (000016K)  |  000001
  01 (000008K)  |  000001
  00 (000004K)  |  000002


db> show allpcpu
Current CPU: 0

cpuid        = 0
dynamic pcpu = 0x3d3f00
curthread    = 0xc38b8ae0: pid 10 tid 100002 "idle: cpu0"
curpcb       = 0xe4c6de98
fpcurthread  = 0xc4267ae0: pid 639 "powerd"
idlethread   = 0xc38b8ae0: tid 100002 "idle: cpu0"
curpmap      = 0xc0967fa4
curvnet      = 0

cpuid        = 1
dynamic pcpu = 0x13accf00
curthread    = 0xc38b8740: pid 10 tid 100003 "idle: cpu1"
curpcb       = 0xe4c70e98
fpcurthread  = 0xc4028740: pid 636 "ntpd"
idlethread   = 0xc38b8740: tid 100003 "idle: cpu1"
curpmap      = 0xc0967fa4
curvnet      = 0

cpuid        = 2
dynamic pcpu = 0x13acdf00
curthread    = 0xc38b83a0: pid 10 tid 100004 "idle: cpu2"
curpcb       = 0xe4c73e98
fpcurthread  = none
idlethread   = 0xc38b83a0: tid 100004 "idle: cpu2"
curpmap      = 0
curvnet      = 0

cpuid        = 3
dynamic pcpu = 0x24426f00
curthread    = 0xc38b8000: pid 10 tid 100005 "idle: cpu3"
curpcb       = 0xe4c76e98
fpcurthread  = 0xc4267ae0: pid 639 "powerd"
idlethread   = 0xc38b8000: tid 100005 "idle: cpu3"
curpmap      = 0xc0967fa4
curvnet      = 0

db> 

At one point before the hangup top -CawPores
showed:

Mem: 8308K Active, 363M Inact, 11M Laundry, 168M Wired, 88M Buf, 253M Free
Swap: 1536M Total, 1244K Used, 1535M Free

Sometime before it hung up there was:

# poudriere status
SET PORTS   JAIL         BUILD                STATUS         QUEUE BUILT FAIL SKIP IGNORE REMAIN TIME     LOGS
-   default FBSDjailRPI2 2017-12-03_20h38m29s parallel_build    87    32    0    0      0     55 04:32:21 /usr/local/poudriere/data/logs/bulk/FBSDjailRPI2-default/2017-12-03_20h38m29s

The end of the poudriere output looked like:

. . .
[07:59:07] [01] [00:00:00] Building sysutils/dtc | dtc-1.4.5
[08:00:12] [01] [00:01:05] Saved sysutils/dtc | dtc-1.4.5 wrkdir to: /usr/local/poudriere/data/wrkdirs/FBSDjailRPI2-default/default/dtc-1.4.5.tbz
[08:00:14] [01] [00:01:07] Finished sysutils/dtc | dtc-1.4.5: Failed: build
[08:00:14] [01] [00:01:07] Skipping sysutils/u-boot-rpi2 | u-boot-rpi2-2017.09.00: Dependent port sysutils/dtc | dtc-1.4.5 failed
[08:00:15] [01] [00:00:00] Building devel/binutils | binutils-2.28,1

(It looks like a rpi2 does not build its own
sysutils/u-boot-rpi2 .)

The world and kernel were head -r326192:

FreeBSD 12.0-CURRENT  r326192M arm
FreeBSD clang vers 5.0.0svn)

(M is mostly from some powerpc64 and
powerpc material: I build the same
source for everything generally.)

/usr/ports for the ports build was at
-r455204 (last before FLAVORS being
enabled).

I historically have not built ports on
a rpi2. So this is not a comparison with
past results.

===
Mark Millard
markmi at dsl-only.net
Received on Wed Dec 06 2017 - 07:44:44 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:41:14 UTC