write(2) returns ERR#12 'Cannot allocate memory' ?

[Ryan Stone]

You could try running this (lightly tested) DTrace script to narrow down
where the error comes from.  Be warned that there can be false positives.
I tried to filter out the ones I saw in my quick tests but you may see
others.

#!/usr/sbin/dtrace -s

#pragma D option quiet

syscall::write:entry
{
    self->in_write = 1;
}

fbt::lapic_handle_timer:entry
{
    self->in_timer = 1;
}

fbt::lapic_handle_timer:return
{
    self->in_timer = 0;
}

fbt:::return
/ self->in_write && !self->in_timer && probefunc != "tcp_addoptions" &&
probefunc != "maybe_yield" && probefunc != "sched_pickcpu" && arg1 == 12 /
{
    printf("Returned %d from %s\n", arg1, probefunc);
}

syscall::write:return
{
    self->in_write = 0;
}


On Sun, Mar 20, 2016 at 11:49 PM, Jim Berilla <
X9Y9NWTX8KC at falstaff.mae.cwru.edu> wrote:

> I've been trying to use the program gdrive-freebsd-x64 (downloaded from
> github) to upload some files to Google Drive.  One of the files is 140 GB
> in size.  Out of four tries, it has failed all four times, after anywhere
> between 27 and 121 GB transferred.
>
> The error message is:
>
> |> Failed to upload file: \
> |> Post https://www.googleapis.com/upload/drive/v3/files?alt=[...]: \
> |> write tcp 129.22.152.23:15810->216.58.216.234:443: \
> |> write: cannot allocate memory
>
> On the last attempt, I ran truss on the process to see what it was doing.
> Here is the output around the time of failure:
>
> |> write(3,"\^W\^C\^C\^P\^X\0\0\0\0\0\t\ti"...,4125) = 4125 (0x101d)
> |> write(3,"\^W\^C\^C\^P\^X\0\0\0\0\0\t\tj."...,4125) = 4125 (0x101d)
> |> write(3,"\^W\^C\^C\^P\^X\0\0\0\0\0\t\tk"...,4125) = 4125 (0x101d)
> |>
> kevent(4,0x0,0,{0x3,EVFILT_WRITE,EV_CLEAR,0,0xd6dcd,0x800bebd20},64,0x0) =
> 1 (0x1)
> |>
> kevent(4,0x0,0,{0x3,EVFILT_WRITE,EV_CLEAR,0,0xd68c4,0x800bebd20},64,0x0) =
> 1 (0x1)
> |> write(3,"\^W\^C\^C\^P\^X\0\0\0\0\0\t\tlm:"...,4125) = 4125 (0x101d)
> |>
> kevent(4,0x0,0,{0x3,EVFILT_WRITE,EV_CLEAR,0,0xd5db0,0x800bebd20},64,0x0) =
> 1 (0x1)
> |>
> kevent(4,0x0,0,{0x3,EVFILT_WRITE,EV_CLEAR,0,0xd5db0,0x800bebd20},64,0x0) =
> 1 (0x1)
> |> write(3,"\^W\^C\^C\^P\^X\0\0\0\0\0\t\tmR"...,4125) = 4125 (0x101d)
> |> write(3,"\^W\^C\^C\^P\^X\0\0\0\0\0\t\tn"...,4125) = 4125 (0x101d)
> |>
> kevent(4,0x0,0,{0x3,EVFILT_WRITE,EV_CLEAR,0,0xd5db0,0x800bebd20},64,0x0) =
> 1 (0x1)
> |> write(3,"\^W\^C\^C\^P\^X\0\0\0\0\0\t\toOQ"...,4125) = 4125 (0x101d)
> |> write(3,"\^W\^C\^C\^P\^X\0\0\0\0\0\t\tp`"...,4125) ERR#12 'Cannot
> allocate memory'
> |>
> kevent(4,0x0,0,{0x3,EVFILT_WRITE,EV_CLEAR,0,0xd488a,0x800bebd20},64,0x0) =
> 1 (0x1)
> |> _umtx_op(0xc8204c4510,UMTX_OP_WAIT_UINT_PRIVATE,0x0,0x0,0x0) = 0 (0x0)
> |> _umtx_op(0xc8204c4510,UMTX_OP_WAKE_PRIVATE,0x1,0x0,0x0) = 0 (0x0)
> |>
> kevent(4,0x0,0,{0x3,EVFILT_WRITE,EV_CLEAR,0,0xd4d93,0x800bebd20},64,0x0) =
> 1 (0x1)
> |> nanosleep({0.000100000 })                        = 0 (0x0)
> |>
> kevent(4,0x0,0,{0x3,EVFILT_WRITE,EV_CLEAR,0,0xd8e07,0x800bebd20},64,0x0) =
> 1 (0x1)
> |> write(3,"\^U\^C\^C\0\^Z\0\0\0\0\0\t\tqn"...,31)  = 31 (0x1f)
>
> If I read that correctly, the write(2) system call is returning a value
> of 12 (ENOMEM).  That is not a value listed under ERRORS in the man page
> for that system call.
>
> I assume FD 3 is a socket opened to one of Google's machines.
>
> This system has 128 GB of physical memory, and I added 256 GB of swap
> after the second failed attempt.  top showed the process had a SIZE of
> about 50 MB.  Nothing[1] else shows evidence of memory starvation.  As
> far as I can tell, there is always at least a couple GB free memory,
> plus another 40 to 80 GB in the ARC.  Not to mention 238 GB of free
> swap now.
>
> Interesting that there is a successful write to the same FD about seven
> lines after the failed one.
>
> On the problem machine, uname -a says:
>
> |> FreeBSD kirara 10.2-RELEASE-p7 FreeBSD 10.2-RELEASE-p7 #0: \
> |> Mon Nov  2 14:19:39 UTC 2015  \
> |> root at amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC  amd64
>
> On a Solaris 11 system, the transfer worked the first time.
>
> On a FreeBSD 10.1-RELEASE-p16 system with only 4 GB of memory, it also
> worked the first time, using the exact same binary as used on the problem
> machine.
>
> I'm familiar with C programming, some on the system level.  But I am new
> to FreeBSD and its file hierarchy.
>
> If someone can point me to the right file, I'd be glad to examine the
> code and try to figure out how it can return this error value.  If
> anyone has any thoughts on this problem, I can explore them.
>
> Thanks.
>
> [1] Or so I thought.  After starting to look into this problem, I was
> logged in remotely to this machine via SSH, and suddenly the terminal
> window closed without warning.  Looking through /var/log/messages, I
> find:
>
> |> Mar 11 10:48:26 kirara sshd[31353]: fatal: Write failed: Cannot
> allocate memory
>
> --
> Jim Berilla, X9Y9NWTX8KC at falstaff.MAE.cwru.edu, +1 216 368 6776
> _______________________________________________
> freebsd-hackers at freebsd.org mailing list
> https://lists.freebsd.org/mailman/listinfo/freebsd-hackers
> To unsubscribe, send any mail to "freebsd-hackers-unsubscribe at freebsd.org"
>