My experience with the RT-AC86U

[Viktor Jaep]

@Martinski: This is all good info but I have a question.
If the stuck nvram get commands have nothing to do with the hardware, how come this only happens on the AC86U?

I let the same loop run on an AC68U last night and it got beyond 870,000 iterations before I finally decided to stop it.

I would have to guess that its a software flaw only present on the 86U... not sure why... you would think they all had some kind of low-level common framework, but this is way out of my league.

 

[Martinski]

Well, it looks like the forum didn't like the script file as an attachment, even with a *.TXT file extension. I can put it in Pastebin if you're interested in trying the script.

Here is the script:

CheckStuckProcCmds.sh - Pastebin.com

Pastebin.com is the number one paste tool since 2002. Pastebin is a website where you can store text online for a set period of time.

pastebin.com

EDIT: Updated link with the latest improved version of the script.

 

[chongnt]

Here is the script:

CheckStuckProcCmds.sh - Pastebin.com

Pastebin.com is the number one paste tool since 2002. Pastebin is a website where you can store text online for a set period of time.

pastebin.com

I see a lot of stucked process. After run few times the list is now cleared. I see today’s file is created and updating in /jffs/.sys/diag_dg/

FOUND: [8]
START_26453: [./CheckStuckProcCmds.sh]
FOUND: [8]
24118 24087 admin    S     3052  0.6   1  0.0 nvram get productid
16800 16788 admin    S     3052  0.6   0  0.0 nvram get lan_ipaddr
 3107     1 admin    S     3052  0.6   1  0.0 nvram get productid
 3065  3063 admin    S     3052  0.6   0  0.0 nvram get http_username
 1236  1235 admin    S     3472  0.7   1  0.0 /usr/sbin/wl -i eth6 noise
 1235  2657 admin    S     3400  0.7   1  0.0 sh -c /usr/sbin/wl -i eth6 noise
 1230     1 admin    S     3052  0.6   0  0.0 nvram get ntpd_enable
 1123 31962 admin    S     3052  0.6   1  0.0 nvram get wl1.2_lanaccess
24087 24085 admin    S     3400  0.7   1  0.0 {YazFi} /bin/sh /jffs/scripts/YazFi check
16788 16784 admin    S     3400  0.7   1  0.0 {YazFi} /bin/sh /jffs/scripts/YazFi check
 3063     1 admin    S     3400  0.7   0  0.0 {cru} /bin/sh /usr/sbin/cru l
 2657     1 admin    S    13696  3.1   1  0.0 conn_diag
31962 31958 admin    S     3668  0.8   1  0.0 {YazFi} /bin/sh /jffs/scripts/YazFi check
24085  1763 admin    S     3400  0.7   0  0.0 /bin/sh -c /jffs/scripts/YazFi check
16784  1763 admin    S     3400  0.7   1  0.0 /bin/sh -c /jffs/scripts/YazFi check
31958  1763 admin    S     3400  0.7   1  0.0 /bin/sh -c /jffs/scripts/YazFi check
 1763     1 admin    S     3400  0.7   1  0.0 crond -l 9
PID: [24118], [193 > 10] secs.
CMD: [kill -9 24118]
FOUND: [7]
EXIT_26453: OK.

 

[Martinski]

@Martinski: This is all good info but I have a question.
If the stuck nvram get commands have nothing to do with the hardware, how come this only happens on the AC86U?

Well, I didn't say that the problems have nothing to do with the hardware. I stated that "I don't think the root cause is a hardware flaw or a failing NVRAM chip." IOW, the problem might be related to some part of the H/W which is a contributing factor, but the H/W may not be the core issue that causes the hangs, or that sets the pieces in motion leading to the hangs. The fact that both the nvram & wl commands (so far, that we know of) are affected in very similar ways seems to point to, perhaps, some software bug in a shared library or module used by both components. But again, this is just speculation since I have not reviewed that code at all. The bottom line is that I don't know. The S/W is complex enough that one could spend a few weeks or months investigating/diagnosing this type of hang if it's a deadlock condition.

 

[Oracle]

Haha. Whatever has the capacity to get stuck has got stuck.
It's like this joke - whatever could go wrong eventually does go wrong.

I would have to guess that its a software flaw only present on the 86U... not sure why... you would think they all had some kind of low-level common framework, but this is way out of my league.

Uhm, I did development for very basic devices 20 years ago. Ugly binary stuff on assembler. My memories are as vague as how to calculate integral equations. Can't do it anymore.

Sure, things have evolved but I don't see the interlocking logic. You don't lock when you read, this works with queues. You send your command to the queue and listen for the response. If any concurrent command modifies the value in the meantime, you just get the new value. Waiting time in these queues is normally in the microseconds scale.
The nvram stores values in key-value pairs. The key (the param name) is mapped to a pointer (to an address in memory) that holds the value. Such basic stuff that having it fail is very unusual.
This seems to me more like an overflowing buffer losing data or some other critical failure in the processing queue. Imagine sending your command with an ID and listening for the response with this ID and the response never comes. Now your command is stuck in indefinite wait which is not handled in the algorithm ('cause it's never supposed to happen), can't move and takes space.

P. S. One of the hardest things about investigating such errors is making them reliably reproducible. Viktor Jaep has achieved just that - we can demonstrate the issue any minute. Now we need an engineer with debugger to sit and trace where the anomaly occurs. Then it might be fixable in code or the defect might be built into a chip and any workaround might cost dramatic loss of performance.

 

[Viktor Jaep]

Dial it back a minute and try

#!/bin/sh
#trap '' HUP INT QUIT ABRT TERM TSTP
(i="0"
while true; do
  i="$(( i + 1 ))";
  for nv in 1 2 3 4 5; do
    unset "state${nv}";
    eval "state${nv}"="$(/bin/nvram get vpn_client${nv}_state)";
    wait
  done
  clear
  echo "$state1" "$state2" "$state3" "$state4" "$state5"
  echo "$i"
done) > /tmp/mynvramerror.log 2>&1 &
exit 0

Nada... locked at 3078, killed the nvram get statement, locked again at 3135

 

[Viktor Jaep]

Here is the script:

CheckStuckProcCmds.sh - Pastebin.com

Pastebin.com is the number one paste tool since 2002. Pastebin is a website where you can store text online for a set period of time.

pastebin.com

That's a wonderful tool you wrote there... thanks so much!!

 

[Martinski]

Haha. Whatever has the capacity to get stuck has got stuck.
It's like this joke - whatever could go wrong eventually does go wrong.



Uhm, I did development for very basic devices 20 years ago. Ugly binary stuff on assembler. My memories are as vague as how to calculate integral equations. Can't do it anymore.

Sure, things have evolved but I don't see the interlocking logic. You don't lock when you read, this works with queues. You send your command to the queue and listen for the response. If any concurrent command modifies the value in the meantime, you just get the new value. Waiting time in these queues is normally in the microseconds scale.

I have written low-level drivers for devices in which both reading & writing into shared memory or disk must be an atomic operation to ensure the integrity of the data being read or written. I can see this being a similar requirement for a database stored in NVRAM. For example, suppose that a process "ABC" wants to read the current value from the "XYZ" key. Then process "EFG" wants to write a newly modified value into the same "XYZ" key. The key value is a series of chars that can be up to 256 bytes, so each read or write operation is actually done in multiple steps (i.e. using multiple CPU instructions & clock cycles). If both processes try to do their task concurrently without ensuring that one of them gets a synchronization lock to make their operation atomic from start to finish, the value read by the ABC process might be in some intermediate state if process EFG is writing to it during the reading process.

The point is that in many situations reading a value must also be performed as an atomic operation, as seen by all other threads, so that a read operation will never get an intermediate or partly complete value if another thread is updating the contents concurrently.

It's similar to how a bank transaction (deposit or withdrawal) must be made as an atomic operation so that all intermediate states/steps in your account are not seen or interfered with by any other transaction.

 

[Oracle]

@Martinski I see what you mean.
I've done the same stuff - writing in transactions to ensure integrity. Reading in transactions - can't remember anything like that. That's handled by the queue. You may be right, I can't imagine reading part of a value and then another process modifying it before the next part is read.

Upon further thought: these nvram values are atomic anyway. It's really interesting what's wrong here.

 

[Martinski]

I see a lot of stucked process. After run few times the list is now cleared. I see today’s file is created and updating in /jffs/.sys/diag_dg/

FOUND: [8]
START_26453: [./CheckStuckProcCmds.sh]
FOUND: [8]
24118 24087 admin    S     3052  0.6   1  0.0 nvram get productid
16800 16788 admin    S     3052  0.6   0  0.0 nvram get lan_ipaddr
3107     1 admin    S     3052  0.6   1  0.0 nvram get productid
3065  3063 admin    S     3052  0.6   0  0.0 nvram get http_username
1236  1235 admin    S     3472  0.7   1  0.0 /usr/sbin/wl -i eth6 noise
1235  2657 admin    S     3400  0.7   1  0.0 sh -c /usr/sbin/wl -i eth6 noise
1230     1 admin    S     3052  0.6   0  0.0 nvram get ntpd_enable
1123 31962 admin    S     3052  0.6   1  0.0 nvram get wl1.2_lanaccess
24087 24085 admin    S     3400  0.7   1  0.0 {YazFi} /bin/sh /jffs/scripts/YazFi check
16788 16784 admin    S     3400  0.7   1  0.0 {YazFi} /bin/sh /jffs/scripts/YazFi check
3063     1 admin    S     3400  0.7   0  0.0 {cru} /bin/sh /usr/sbin/cru l
2657     1 admin    S    13696  3.1   1  0.0 conn_diag
31962 31958 admin    S     3668  0.8   1  0.0 {YazFi} /bin/sh /jffs/scripts/YazFi check
24085  1763 admin    S     3400  0.7   0  0.0 /bin/sh -c /jffs/scripts/YazFi check
16784  1763 admin    S     3400  0.7   1  0.0 /bin/sh -c /jffs/scripts/YazFi check
31958  1763 admin    S     3400  0.7   1  0.0 /bin/sh -c /jffs/scripts/YazFi check
1763     1 admin    S     3400  0.7   1  0.0 crond -l 9
PID: [24118], [193 > 10] secs.
CMD: [kill -9 24118]
FOUND: [7]
EXIT_26453: OK.

Yeah, I saw a similar situation in my router as well with multiple occurrences where the parent thread was either conn_diag & YazFi simply because they call the "guilty" commands a lot during the day.

NOTE: I just checked and the GT-AC5300 router running the stock OEM F/W is exhibiting the same issues as the RT-AC86U with the same stuck commands. I left my script running on all routers I have access to since Monday early morning (and updated today to the latest version), and so far none of the RT-AC68Us are showing a sign of the "stuck process" issue.

 

[Oracle]

If true, this thing about the AC5300 doing the same crap is very good news. It would mean Asus have succeeded replicating the problem, i.e. they are reusing the faulty design. Cool! And they can very well continue to do so.

Now, a note to @SomeWhereOverTheRainBow - I followed how you were trying to capture the error with curiosity. If my assumption of the root cause is correct, it is logically impossible to catch any error from inside the affected system. There would be no error because it is completely unhandled, the process just stops, the flow of data is interrupted. This has to be put in a sort of try-catch construction or hooked to external debugger to collect the values of the variables and any messages.

 

[SomeWhereOverTheRainBow]

If true, this thing about the AC5300 doing the same crap is very good news. It would mean Asus have succeeded replicating the problem, i.e. they are reusing the faulty design. Cool! And they can very well continue to do so.

Now, a note to @SomeWhereOverTheRainBow - I followed how you were trying to capture the error with curiosity. If my assumption of the root cause is correct, it is logically impossible to catch any error from inside the affected system. There would be no error because it is completely unhandled, the process just stops, the flow of data is interrupted. This has to be put in a sort of try-catch construction or hooked to external debugger to collect the values of the variables and any messages.

You are correct since the command must not output anything on failures or hangs. Now if there were only away to catch it when it hangs and kill it. The log was more to see when it failed since we can tail -f the log and see where it hangs. Now if a separate process could parse the log, maybe the process can be killed on hangs.... just food for thought. At @Martinski has given the best possible measure any one can provide at this time. However, the best outcome is for asus to figure this issue out.

 

[dave14305]

I still think someone should strace the nvram commands as they execute.

 

[ColinTaylor]

I still think someone should strace the nvram commands as they execute.

I agree. As it doesn't seem to matter what variable is being read, or how. I'd suggest running something along the lines of this until it hangs:

watch -n 1 strace -r nvram get wan0_enable

 

[eibgrad]

Any kind of deadlock situation implies a multi-threaded situation. But IIRC, @Viktor Jaep was encountering this within a single thread, so all access to nvram was synchronous. Not unless some other process besides his own script can account for asynchronous access of nvram.

As a workaround, it might be possible to create an nvram "wrapper" that implements one-at-a-time semantics, even just to see if it makes a difference.

 

[ColinTaylor]

Not unless some other process besides his own script can account for asynchronous access of nvram.

This has always been my suspicion. The router's normal operation periodically writes information into nvram. Bear in mind that some nvram variables are also transparently redirected to /jffs, which in turn is constantly being written to. Lots of opportunities for deadlock conditions.

 

[Viktor Jaep]

Things have definitely gotten serious... we've got *4 part-of-the-furniture members discussing this issue. @ColinTaylor or @dave14305 ... I would love to know how to apply your watch/strace statement to the poc script and I'd happily be your guinea pig in the name of science. I'm all ears on a "wrapper" as well, @eibgrad! I'm sure @SomeWhereOverTheRainBow has a script in his backpocket to tie this all together in a pretty bow as well, lol!

 

[Viktor Jaep]

And with that post, I have magically transitioned into the "Very Senior Member" category. LOL

 

[dave14305]

Hung one.

Every 0s: strace -r nvram get wan0_enable                                                                  2022-06-14 19:15:30

     0.000000 execve("/bin/nvram", ["nvram", "get", "wan0_enable"], 0x7fea378f88 /* 18 vars */ <unfinished ...>
     0.000698 [ Process PID=1098 runs in 32 bit mode. ]
strace: WARNING: Proper structure decoding for this personality is not supported, please consider building strace with mpers support enabled.
     0.000039 <... execve resumed>)     = 0
     0.000091 brk(NULL)                 = 0x42e000
     0.000057 uname({sysname="Linux", nodename="router", ...}) = 0
     0.000094 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7124000
     0.000055 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
     0.000134 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
     0.000069 fstat64(3, 0xffb8e450)    = 0
     0.000057 mmap2(NULL, 10528, PROT_READ, MAP_PRIVATE, 3, 0) = 0xf7121000
     0.000042 close(3)                  = 0
     0.000051 open("/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
     0.000062 read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0xm\1\0004\0\0\0"..., 512) = 512
     0.000052 fstat64(3, 0xffb8e490)    = 0
     0.000041 mmap2(NULL, 1299824, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6fb8000
     0.000046 mprotect(0xf70e0000, 65536, PROT_NONE) = 0
     0.000196 mmap2(0xf70f0000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x128000) = 0xf70f0000
     0.000063 mmap2(0xf70f3000, 9584, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf70f3000
     0.000059 close(3)                  = 0
     0.000056 open("/lib/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = 3
     0.000048 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\254\317\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffb8e478)    = 0
     0.000038 mmap2(NULL, 182372, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6f8b000
     0.000044 mprotect(0xf6fa8000, 61440, PROT_NONE) = 0
     0.000072 mmap2(0xf6fb7000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c000) = 0xf6fb7000
     0.000060 close(3)                  = 0
     0.000048 open("/lib/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
     0.000046 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0(\t\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffb8e460)    = 0
     0.000038 mmap2(NULL, 73912, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6f78000
     0.000044 mprotect(0xf6f7a000, 61440, PROT_NONE) = 0
     0.000046 mmap2(0xf6f89000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0xf6f89000
     0.000125 close(3)                  = 0
     0.000044 open("/lib/libnvram.so", O_RDONLY|O_CLOEXEC) = 3
     0.000047 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\08\t\0\0004\0\0\0"..., 512) = 512
     0.000046 fstat64(3, 0xffb8e448)    = 0
     0.000037 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7120000
     0.000072 mmap2(NULL, 69528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6f67000
     0.000046 mprotect(0xf6f68000, 61440, PROT_NONE) = 0
     0.000048 mmap2(0xf6f77000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0) = 0xf6f77000
     0.000057 close(3)                  = 0
     0.000044 open("/usr/lib/libshared.so", O_RDONLY|O_CLOEXEC) = 3
     0.000050 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\214X\1\0004\0\0\0"..., 512) = 512
     0.000074 fstat64(3, 0xffb8e430)    = 0
     0.000038 mmap2(NULL, 646528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6ec9000
     0.000044 mprotect(0xf6f36000, 65536, PROT_NONE) = 0
     0.000047 mmap2(0xf6f46000, 45056, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6d000) = 0xf6f46000
     0.000060 mmap2(0xf6f51000, 89472, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf6f51000
     0.000081 close(3)                  = 0
     0.000050 open("/lib/libwlcsm.so", O_RDONLY|O_CLOEXEC) = 3
     0.000048 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\200\34\0\0004\0\0\0"..., 512) = 512
     0.000088 fstat64(3, 0xffb8e418)    = 0
     0.000138 mmap2(NULL, 90092, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6eb3000
     0.000049 mprotect(0xf6eb8000, 61440, PROT_NONE) = 0
     0.000046 mmap2(0xf6ec7000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0xf6ec7000
     0.000067 close(3)                  = 0
     0.000056 open("/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
     0.000048 read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\\I\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffb8e250)    = 0
     0.000038 mmap2(NULL, 164436, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf6e8a000
     0.000045 mprotect(0xf6e9f000, 65536, PROT_NONE) = 0
     0.000050 mmap2(0xf6eaf000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0xf6eaf000
     0.000076 mmap2(0xf6eb1000, 4692, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf6eb1000
     0.000058 close(3)                  = 0
     0.000071 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf711f000
     0.000051 set_tls(0xf711f780)       = 0
     0.000260 mprotect(0xf70f0000, 8192, PROT_READ) = 0
     0.000090 mprotect(0xf6eaf000, 4096, PROT_READ) = 0
     0.000369 mprotect(0xf6f89000, 4096, PROT_READ) = 0
     0.000164 mprotect(0xf7125000, 4096, PROT_READ) = 0
     0.000052 munmap(0xf7121000, 10528) = 0
     0.000054 set_tid_address(0xf711f328) = 1098
     0.000036 set_robust_list(0xf711f330, 12) = 0
     0.000061 rt_sigaction(SIGRTMIN, {sa_handler=0xf6e8e278, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0xf6fe4b10}, NULL, 8) = 0
     0.000064 rt_sigaction(SIGRT_1, {sa_handler=0xf6e8e35c, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0xf6fe4b10}, NULL, 8) = 0
     0.000063 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
     0.000055 ugetrlimit(RLIMIT_STACK, {rlim_cur=2048*1024, rlim_max=RLIM_INFINITY}) = 0
     0.000210 mmap2(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf6e69000
     0.000084 stat64("/jffs", 0xffb8e7a0) = 0
     0.000055 stat64("/jffs/nvram_war", 0xffb8e7a0) = 0
     0.000117 socket(AF_NETLINK, SOCK_RAW, 0x1f /* NETLINK_??? */) = 3
     0.000078 bind(3, {sa_family=AF_NETLINK, nl_pid=1098, nl_groups=00000000}, 12) = -1 EADDRINUSE (Address already in use)
     0.000073 brk(NULL)                 = 0x42e000
     0.000049 brk(0x44f000)             = 0x44f000
     0.000052 sendmsg(3, {msg_name=0xcffb8e830, msg_namelen=-4659160, msg_iov=NULL, msg_iovlen=0, msg_control=0xf6ec7d74ffb8ee04, msg_controllen=4142697156, msg_flags=MSG_DONTROUTE|MSG_CTRUNC|MSG_PROBE|MSG_TRUNC|MSG_DONTWAIT|MSG_WAITALL|MSG_FIN|MSG_CONFIRM|MSG_ERRQUEUE|MSG_NOSIGNAL|MSG_MORE|MSG_NO_SHARED_FRAGS|MSG_ZEROCOPY|MSG_FASTOPEN|MSG_CMSG_CLOEXEC|MSG_CMSG_COMPAT|0x1bb00000}, 0) = 36
     0.000178 recvmsg(3,

 

[dave14305]

Normal one:

# strace -r nvram get wan0_enable
     0.000000 execve("/bin/nvram", ["nvram", "get", "wan0_enable"], 0x7ff58279a8 /* 18 vars */ <unfinished ...>
     0.000618 [ Process PID=1356 runs in 32 bit mode. ]
strace: WARNING: Proper structure decoding for this personality is not supported, please consider building strace with mpers support enabled.
     0.000041 <... execve resumed>)     = 0
     0.000064 brk(NULL)                 = 0x76d000
     0.000056 uname({sysname="Linux", nodename="router", ...}) = 0
     0.000093 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7649000
     0.000059 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
     0.000128 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
     0.000068 fstat64(3, 0xffae1600)    = 0
     0.000050 mmap2(NULL, 10528, PROT_READ, MAP_PRIVATE, 3, 0) = 0xf7646000
     0.000041 close(3)                  = 0
     0.000051 open("/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
     0.000048 read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0xm\1\0004\0\0\0"..., 512) = 512
     0.000051 fstat64(3, 0xffae1640)    = 0
     0.000041 mmap2(NULL, 1299824, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf74dd000
     0.000047 mprotect(0xf7605000, 65536, PROT_NONE) = 0
     0.000055 mmap2(0xf7615000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x128000) = 0xf7615000
     0.000062 mmap2(0xf7618000, 9584, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf7618000
     0.000060 close(3)                  = 0
     0.000055 open("/lib/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = 3
     0.000049 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\254\317\0\0004\0\0\0"..., 512) = 512
     0.000048 fstat64(3, 0xffae1628)    = 0
     0.000038 mmap2(NULL, 182372, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf74b0000
     0.000044 mprotect(0xf74cd000, 61440, PROT_NONE) = 0
     0.000047 mmap2(0xf74dc000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c000) = 0xf74dc000
     0.000060 close(3)                  = 0
     0.000049 open("/lib/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
     0.000047 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0(\t\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffae1610)    = 0
     0.000038 mmap2(NULL, 73912, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf749d000
     0.000044 mprotect(0xf749f000, 61440, PROT_NONE) = 0
     0.000047 mmap2(0xf74ae000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0xf74ae000
     0.000069 close(3)                  = 0
     0.000043 open("/lib/libnvram.so", O_RDONLY|O_CLOEXEC) = 3
     0.000047 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\08\t\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffae15f8)    = 0
     0.000037 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7645000
     0.000046 mmap2(NULL, 69528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf748c000
     0.000045 mprotect(0xf748d000, 61440, PROT_NONE) = 0
     0.000046 mmap2(0xf749c000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0) = 0xf749c000
     0.000056 close(3)                  = 0
     0.000042 open("/usr/lib/libshared.so", O_RDONLY|O_CLOEXEC) = 3
     0.000049 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\214X\1\0004\0\0\0"..., 512) = 512
     0.000046 fstat64(3, 0xffae15e0)    = 0
     0.000038 mmap2(NULL, 646528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf73ee000
     0.000044 mprotect(0xf745b000, 65536, PROT_NONE) = 0
     0.000045 mmap2(0xf746b000, 45056, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6d000) = 0xf746b000
     0.000060 mmap2(0xf7476000, 89472, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf7476000
     0.000061 close(3)                  = 0
     0.000051 open("/lib/libwlcsm.so", O_RDONLY|O_CLOEXEC) = 3
     0.000049 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\200\34\0\0004\0\0\0"..., 512) = 512
     0.000047 fstat64(3, 0xffae15c8)    = 0
     0.000038 mmap2(NULL, 90092, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf73d8000
     0.000045 mprotect(0xf73dd000, 61440, PROT_NONE) = 0
     0.000047 mmap2(0xf73ec000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0xf73ec000
     0.000068 close(3)                  = 0
     0.000053 open("/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
     0.000049 read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\\I\0\0004\0\0\0"..., 512) = 512
     0.000048 fstat64(3, 0xffae1400)    = 0
     0.000038 mmap2(NULL, 164436, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xf73af000
     0.000044 mprotect(0xf73c4000, 65536, PROT_NONE) = 0
     0.000054 mmap2(0xf73d4000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0xf73d4000
     0.000061 mmap2(0xf73d6000, 4692, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xf73d6000
     0.000056 close(3)                  = 0
     0.000075 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7644000
     0.000052 set_tls(0xf7644780)       = 0
     0.000194 mprotect(0xf7615000, 8192, PROT_READ) = 0
     0.000087 mprotect(0xf73d4000, 4096, PROT_READ) = 0
     0.000377 mprotect(0xf74ae000, 4096, PROT_READ) = 0
     0.000091 mprotect(0xf764a000, 4096, PROT_READ) = 0
     0.000050 munmap(0xf7646000, 10528) = 0
     0.000052 set_tid_address(0xf7644328) = 1356
     0.000035 set_robust_list(0xf7644330, 12) = 0
     0.000049 rt_sigaction(SIGRTMIN, {sa_handler=0xf73b3278, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0xf7509b10}, NULL, 8) = 0
     0.000063 rt_sigaction(SIGRT_1, {sa_handler=0xf73b335c, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0xf7509b10}, NULL, 8) = 0
     0.000063 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
     0.000057 ugetrlimit(RLIMIT_STACK, {rlim_cur=2048*1024, rlim_max=RLIM_INFINITY}) = 0
     0.000180 mmap2(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf738e000
     0.000086 stat64("/jffs", 0xffae1950) = 0
     0.000057 stat64("/jffs/nvram_war", 0xffae1950) = 0
     0.000093 socket(AF_NETLINK, SOCK_RAW, 0x1f /* NETLINK_??? */) = 3
     0.000076 bind(3, {sa_family=AF_NETLINK, nl_pid=1356, nl_groups=00000000}, 12) = 0
     0.000065 brk(NULL)                 = 0x76d000
     0.000035 brk(0x78e000)             = 0x78e000
     0.000050 open("/proc/sys/kernel/pid_max", O_RDONLY) = 4
     0.000070 fstat64(4, 0xffae1858)    = 0
     0.000037 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7648000
     0.000042 read(4, "32768\n", 1024)  = 6
     0.000085 close(4)                  = 0
     0.000040 munmap(0xf7648000, 4096)  = 0
     0.000047 socket(AF_NETLINK, SOCK_RAW, 0x1f /* NETLINK_??? */) = 4
     0.000044 bind(4, {sa_family=AF_NETLINK, nl_pid=34126, nl_groups=00000000}, 12) = 0
     0.000052 sendmsg(3, {msg_name=0xcffae19e0, msg_namelen=-5367336, msg_iov=NULL, msg_iovlen=0, msg_control=0xf73ecd74ffae2e04, msg_controllen=4148091588, msg_flags=MSG_DONTROUTE|MSG_CTRUNC|MSG_TRUNC|MSG_WAITALL|MSG_SYN|MSG_CONFIRM|MSG_RST|MSG_SENDPAGE_NOTLAST|MSG_BATCH|MSG_NO_SHARED_FRAGS|MSG_ZEROCOPY|MSG_FASTOPEN|MSG_CMSG_CLOEXEC|MSG_CMSG_COMPAT|0x1ba00000}, 0) = 36
     0.000138 recvmsg(3, {msg_name=0xcffae19e0, msg_namelen=-5367336, msg_iov=NULL, msg_iovlen=0, msg_control=0xffae2e0400000000, msg_controllen=17815917715420794228, msg_flags=0}, 0) = 48
     0.000272 fstat64(1, 0xffae1980)    = 0
     0.000040 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xf7648000
     0.000047 write(1, "1\n", 21
)        = 2
     0.000046 munmap(0xf738e000, 135168) = 0
     0.000073 exit_group(0)             = ?
     0.000224 +++ exited with 0 +++