Date: Tue, 8 Jul 2014 13:56:44 +0100 From: Vlad Galu <galu@packetdam.com> To: John Baldwin <jhb@freebsd.org> Cc: freebsd-stable@freebsd.org Subject: Re: Weird ISR accounting in 10-STABLE Message-ID: <CABN%2B6JmjUVg1z-nC1LmZNYeWffWyKzhrP7=6B_q5KSHav2ocfA@mail.gmail.com> In-Reply-To: <CABN%2B6JnjgGy_S1Sq-a28TgQ20A-KXn1J-F7TsAx4qEPgUFSx8Q@mail.gmail.com> References: <CABN%2B6JmYP4U1vT7r7vy810TUzdH%2BqG=zuHRnNU9fDzOF0J-skg@mail.gmail.com> <201406231614.51004.jhb@freebsd.org> <CABN%2B6JnjgGy_S1Sq-a28TgQ20A-KXn1J-F7TsAx4qEPgUFSx8Q@mail.gmail.com>
next in thread | previous in thread | raw e-mail | index | archive | help
The symptom has reappeared, although interestingly enough I can't spot
anything out of the ordinary in this DTrace output:
-- cut here --
FUNCTION COUNT PCNT
zfs.ko`atomic_cas_32 1 0.0%
kernel`pmap_try_insert_pv_entry 1 0.0%
kernel`bounce_bus_dmamap_complete 1 0.0%
kernel`prison_priv_check 1 0.0%
kernel`sys_sendto 1 0.0%
kernel`m_prepend 1 0.0%
zfs.ko`zio_vdev_io_assess 1 0.0%
kernel`vm_map_pmap_enter 1 0.0%
kernel`vrele 1 0.0%
kernel`tcp_sack_doack 1 0.0%
zfs.ko`dmu_zfetch 1 0.0%
kernel`VOP_GETATTR_APV 1 0.0%
kernel`pipe_poll 1 0.0%
zfs.ko`zfs_zaccess_aces_check 1 0.0%
kernel`vn_syncer_add_to_worklist 1 0.0%
kernel`dofileread 1 0.0%
kernel`sys_select 1 0.0%
kernel`fget_write 1 0.0%
kernel`in_cksum_hdr 1 0.0%
zfs.ko`bpobj_iterate_impl 1 0.0%
kernel`mb_dtor_pack 1 0.0%
kernel`sx_downgrade_ 1 0.0%
kernel`pf_normalize_tcp 1 0.0%
kernel`umtx_key_get 1 0.0%
kernel`knlist_mtx_lock 1 0.0%
zfs.ko`dmu_object_size_from_db 1 0.0%
kernel`pmap_enter_quick_locked 1 0.0%
kernel`rijndaelKeySetupEnc 1 0.0%
kernel`pmap_promote_pde 1 0.0%
kernel`ehci_interrupt 1 0.0%
kernel`prison_check 1 0.0%
kernel`sysctl_root 1 0.0%
kernel`ttyoutq_read_uio 1 0.0%
kernel`rijndaelEncrypt 1 0.0%
kernel`vm_fault 1 0.0%
kernel`mac_cred_check_visible 1 0.0%
kernel`vfs_unbusy 1 0.0%
kernel`in_rtalloc_ign 1 0.0%
kernel`knote_enqueue 1 0.0%
kernel`atomic_fetchadd_int 1 0.0%
kernel`vm_page_zero_idle_wakeup 1 0.0%
h_ertt.ko`ertt_packet_measurement_hook 1 0.0%
zfs.ko`spa_config_enter 1 0.0%
kernel`cv_broadcastpri 1 0.0%
zfs.ko`trim_thread 1 0.0%
zfs.ko`SHA256_Final 1 0.0%
kernel`kern_statat_vnhook 1 0.0%
kernel`cap_rights 1 0.0%
kernel`sosend 1 0.0%
kernel`vputx 1 0.0%
dtrace.ko`dtrace_state_clean 1 0.0%
kernel`tvtohz 1 0.0%
zfs.ko`dbuf_write_physdone 1 0.0%
kernel`atkbd_lock 1 0.0%
kernel`getmicrouptime 1 0.0%
zfs.ko`zio_execute 1 0.0%
kernel`sowakeup 1 0.0%
kernel`syscall_thread_exit 1 0.0%
zfs.ko`dnode_sync 1 0.0%
kernel`should_yield 1 0.0%
kernel`VOP_ACCESS_APV 1 0.0%
kernel`__cap_rights_is_set 1 0.0%
kernel`kqueue_release 1 0.0%
kernel`sleepq_timedwait_sig 1 0.0%
kernel`g_io_request 1 0.0%
zfs.ko`list_head 1 0.0%
kernel`mac_cred_label_free 1 0.0%
kernel`bus_dma_run_filter 1 0.0%
kernel`vget 1 0.0%
kernel`ahci_ch_intr_direct 1 0.0%
kernel`_vm_map_lock_read 1 0.0%
kernel`vn_seek 1 0.0%
kernel`taskqueue_member 1 0.0%
zfs.ko`dbuf_write_ready 1 0.0%
zfs.ko`range_tree_add 1 0.0%
kernel`vm_object_deallocate 1 0.0%
kernel`random_kthread 1 0.0%
kernel`random_harvest 1 0.0%
kernel`vm_map_insert 1 0.0%
kernel`pfind_locked 1 0.0%
kernel`devfs_populate_vp 1 0.0%
kernel`cr_cansee 1 0.0%
kernel`fill_kinfo_proc 1 0.0%
kernel`_sx_slock 1 0.0%
kernel`pmap_remove 1 0.0%
kernel`vm_page_dequeue 1 0.0%
kernel`callout_reset_sbt_on 1 0.0%
zfs.ko`zio_notify_parent 1 0.0%
kernel`vfs_cache_lookup 1 0.0%
kernel`uma_zone_exhausted_nolock 1 0.0%
kernel`priv_check_cred 1 0.0%
kernel`in_delayed_cksum 1 0.0%
kernel`ugidfw_check_vp 1 0.0%
kernel`_fget 1 0.0%
zfs.ko`ddt_get_dedup_stats 1 0.0%
kernel`tcp_output 1 0.0%
kernel`swap_reserve_by_cred 1 0.0%
kernel`vm_radix_lookup 1 0.0%
kernel`_sx_sunlock 1 0.0%
kernel`p_cansee 1 0.0%
kernel`in_clsroute 1 0.0%
kernel`kern_ioctl 1 0.0%
dtrace.ko`dtrace_trap 1 0.0%
zfs.ko`range_tree_space 1 0.0%
kernel`mac_vnode_check_stat 1 0.0%
zfs.ko`zfs_freebsd_getattr 1 0.0%
kernel`randomdev_hash_iterate 1 0.0%
kernel`pfi_match_addr 1 0.0%
kernel`mac_vnode_check_read 1 0.0%
zfs.ko`avl_remove 1 0.0%
kernel`kbdc_data_ready 1 0.0%
kernel`sbsndptr 1 0.0%
kernel`vref 1 0.0%
kernel`vm_map_entry_link 1 0.0%
kernel`lookup 1 0.0%
kernel`kern_select 1 0.0%
kernel`softclock_call_cc 1 0.0%
kernel`devfs_find 2 0.0%
kernel`vinactive 2 0.0%
kernel`intr_event_execute_handlers 2 0.0%
kernel`ng_ether_output 2 0.0%
kernel`thread_lock_flags_ 2 0.0%
kernel`maybe_yield 2 0.0%
kernel`pmap_remove_pte 2 0.0%
kernel`soreceive 2 0.0%
kernel`pagecopy 2 0.0%
kernel`mac_socket_check_send 2 0.0%
kernel`pf_match_port 2 0.0%
kernel`pmap_is_prefaultable 2 0.0%
kernel`_sleep 2 0.0%
zfs.ko`zfs_acl_next_ace 2 0.0%
kernel`wakeupshlk 2 0.0%
kernel`get_pv_entry 2 0.0%
kernel`mac_inpcb_check_deliver 2 0.0%
kernel`pmap_kextract 2 0.0%
kernel`kern_writev 2 0.0%
kernel`pf_match_addr 2 0.0%
kernel`m_getm2 2 0.0%
kernel`ip_savecontrol 2 0.0%
kernel`g_io_deliver 2 0.0%
kernel`PHYS_TO_VM_PAGE 2 0.0%
zfs.ko`buf_hash_find 2 0.0%
kernel`pf_check_in 2 0.0%
kernel`fget 2 0.0%
kernel`_cv_timedwait_sig_sbt 2 0.0%
kernel`ip_ipsec_output 2 0.0%
kernel`vm_page_alloc 2 0.0%
zfs.ko`dbuf_find 2 0.0%
kernel`trap_pfault 2 0.0%
kernel`ahci_ch_intr_main 2 0.0%
kernel`_mtx_trylock_flags_ 2 0.0%
kernel`arpresolve 2 0.0%
kernel`in_localip 2 0.0%
kernel`ipsec4_in_reject 2 0.0%
kernel`vm_map_delete 2 0.0%
kernel`mac_netinet_fragment 2 0.0%
kernel`sbappendaddr_locked 2 0.0%
kernel`binuptime 3 0.0%
kernel`sopoll 3 0.0%
kernel`ip_ipsec_fwd 3 0.0%
kernel`atomic_add_long 3 0.0%
kernel`bounce_bus_dmamap_unload 3 0.0%
kernel`sysctl_kern_proc 3 0.0%
kernel`m_dup_pkthdr 3 0.0%
kernel`VOP_LOCK1_APV 3 0.0%
kernel`devfs_write_f 3 0.0%
kernel`vfs_stdsync 3 0.0%
kernel`getbinuptime 3 0.0%
kernel`mac_socket_check_receive 3 0.0%
kernel`syscall_thread_enter 3 0.0%
kernel`m_copyback 3 0.0%
kernel`pf_step_out_of_anchor 3 0.0%
kernel`pf_check_out 3 0.0%
kernel`vm_fault_hold 3 0.0%
kernel`netisr_dispatch_src 3 0.0%
kernel`vm_radix_insert 3 0.0%
kernel`__cap_rights_set 3 0.0%
kernel`ipsec4_checkpolicy 3 0.0%
kernel`mac_socket_check_connect 3 0.0%
kernel`sched_userret 3 0.0%
kernel`cache_lookup 3 0.0%
kernel`soo_poll 4 0.0%
kernel`mac_inpcb_create_mbuf 4 0.0%
kernel`pf_normalize_ip 4 0.0%
kernel`sosend_dgram 4 0.0%
kernel`ip_fragment 4 0.0%
kernel`devfs_read_f 4 0.0%
kernel`__rw_wlock_hard 4 0.0%
kernel`ip_rtaddr 4 0.0%
kernel`spinlock_enter 4 0.0%
kernel`cap_check 4 0.0%
kernel`m_adj 4 0.0%
kernel`trap 4 0.0%
kernel`udp_append 4 0.0%
kernel`pagezero 4 0.0%
zfs.ko`sa_attr_op 4 0.0%
kernel`ether_demux 4 0.0%
zfs.ko`lz4_decompress 4 0.0%
kernel`cap_rights_contains 4 0.0%
kernel`sbappendaddr_locked_internal 4 0.0%
kernel`ip_ipsec_filtertunnel 4 0.0%
kernel`kern_readv 5 0.0%
kernel`kern_kevent 5 0.0%
kernel`ifa_ref 5 0.0%
kernel`random_process_event 5 0.0%
kernel`pmap_enter 5 0.0%
kernel`bus_dmamap_load_mbuf_sg 5 0.0%
kernel`knote 5 0.0%
kernel`SHA256_Update 5 0.0%
kernel`mnt_vnode_next_active 6 0.0%
kernel`kern_recvit 6 0.0%
kernel`sbuf_bcat 6 0.0%
kernel`uiomove_faultflag 6 0.0%
kernel`random_harvestq_internal 6 0.0%
kernel`ifa_free 6 0.0%
kernel`_sx_xlock 6 0.0%
kernel`ip_randomid 6 0.0%
kernel`in_lltable_lookup 6 0.0%
kernel`pfi_kif_match 7 0.0%
kernel`lock_mtx 7 0.0%
kernel`ipsec_getpolicybysock 7 0.0%
kernel`mac_socket_check_poll 7 0.0%
kernel`copyinuio 7 0.0%
kernel`udp_input 7 0.0%
kernel`tunstart 7 0.0%
kernel`dev_relthread 7 0.0%
kernel`_sx_xunlock 7 0.0%
kernel`tsc_get_timecount_low_lfence 7 0.0%
kernel`kern_sendit 7 0.0%
kernel`seltdwait 8 0.0%
kernel`cpu_set_syscall_retval 8 0.0%
kernel`tunwrite 8 0.0%
kernel`in_pcblookup_hash 8 0.0%
kernel`in_cksum_skip 9 0.0%
kernel`_bus_dmamap_sync 9 0.0%
kernel`ip_fastforward 9 0.0%
kernel`pf_change_ap 9 0.0%
zfs.ko`lzjb_compress 10 0.0%
kernel`re_newbuf 10 0.0%
kernel`vfs_msync 10 0.0%
kernel`bounce_bus_dmamap_sync 10 0.0%
kernel`pfr_update_stats 10 0.0%
kernel`soreceive_dgram 10 0.0%
kernel`udp_send 10 0.0%
kernel`devfs_poll_f 10 0.0%
kernel`rtalloc_ign_fib 11 0.0%
kernel`ether_output 11 0.0%
kernel`tunoutput 12 0.0%
kernel`selfdfree 12 0.0%
kernel`ipsec_setspidx 12 0.0%
kernel`m_copydata 13 0.0%
kernel`re_start_locked 13 0.0%
kernel`pf_test_state_udp 13 0.0%
kernel`free 13 0.0%
kernel`pf_get_translation 13 0.0%
kernel`memcpy 13 0.0%
kernel`arc4rand 14 0.0%
kernel`in_broadcast 15 0.0%
kernel`pf_purge_expired_src_nodes 15 0.0%
kernel`selrecord 15 0.0%
kernel`doselwakeup 16 0.0%
kernel`mb_free_ext 16 0.0%
kernel`mb_ctor_pack 16 0.0%
kernel`malloc 16 0.0%
kernel`bounce_bus_dmamap_load_buffer 16 0.0%
kernel`pf_test_state_tcp 17 0.0%
kernel`sopoll_generic 18 0.0%
kernel`tunread 18 0.0%
kernel`ip_forward 19 0.0%
kernel`cpu_fetch_syscall_args 19 0.0%
kernel`fpudna 19 0.0%
kernel`fget_unlocked 20 0.0%
kernel`key_allocsp 20 0.0%
kernel`jenkins_hash32 20 0.0%
kernel`userret 21 0.0%
kernel`ip_input 23 0.0%
kernel`in_cksumdata 23 0.0%
kernel`ether_nh_input 23 0.0%
kernel`if_transmit 24 0.0%
kernel`tunpoll 24 0.0%
kernel`devvn_refthread 29 0.0%
kernel`re_start 30 0.0%
kernel`pf_purge_expired_states 30 0.0%
kernel`re_txeof 31 0.0%
kernel`copyin 32 0.0%
kernel`__mnt_vnode_next_all 32 0.0%
kernel`ithread_loop 35 0.0%
kernel`amd64_syscall 36 0.0%
kernel`re_rxeof 36 0.0%
kernel`__cap_rights_init 36 0.0%
kernel`sched_idletd 39 0.0%
kernel`ip_output 39 0.0%
zfs.ko`fletcher_4_native 39 0.0%
kernel`pfr_match_addr 47 0.0%
kernel`pf_find_state 48 0.0%
kernel`sys_poll 51 0.0%
kernel`__mtx_lock_sleep 52 0.0%
kernel`m_tag_delete_nonpersistent 54 0.0%
kernel`swi_net 56 0.0%
kernel`in6_rtalloc1 58 0.0%
kernel`mb_dtor_mbuf 59 0.0%
kernel`0xffffffff80 67 0.0%
kernel`pf_test 75 0.0%
kernel`pf_match_translation 78 0.0%
kernel`copyout 94 0.0%
kernel`mac_mbuf_to_label 97 0.0%
kernel`ip6_ipsec_filtertunnel 99 0.0%
kernel`pf_test_rule 102 0.0%
kernel`nd6_output 107 0.0%
kernel`m_tag_delete_chain 126 0.0%
kernel`SHA256_Transform 132 0.0%
kernel`netisr_select_cpuid 135 0.0%
kernel`mac_mbuf_init 141 0.0%
kernel`mac_policy_sunlock_nosleep 142 0.0%
kernel`netisr_queue 155 0.0%
kernel`key_havesp 162 0.0%
kernel`ipsec_in_reject 164 0.0%
kernel`m_freem 169 0.0%
kernel`critical_exit 170 0.0%
kernel`ipsec6_in_reject 173 0.0%
kernel`pf_check6_in 173 0.0%
kernel`mac_policy_slock_nosleep 207 0.0%
kernel`m_tag_copy_chain 213 0.0%
kernel`pf_check6_out 216 0.0%
kernel`critical_enter 216 0.0%
kernel`key_allocsp_default 229 0.1%
kernel`in6_lltable_lookup 263 0.1%
kernel`if_simloop 295 0.1%
kernel`in6_clearscope 297 0.1%
kernel`looutput 366 0.1%
kernel`ipsec_getpolicybyaddr 404 0.1%
kernel`mb_ctor_mbuf 453 0.1%
kernel`rtfree 456 0.1%
kernel`mac_netinet6_nd6_send 498 0.1%
kernel`uma_zfree_arg 550 0.1%
kernel`nd6_output_lle 663 0.2%
kernel`uma_zalloc_arg 702 0.2%
kernel`re_intr_msi 871 0.2%
kernel`spinlock_exit 884 0.2%
kernel`m_copym 920 0.2%
kernel`bcopy 956 0.2%
kernel`pfil_run_hooks 1024 0.2%
kernel`netisr_queue_internal 1037 0.2%
kernel`cpu_idle_spin 1045 0.2%
kernel`mac_ifnet_create_mbuf 1134 0.3%
kernel`_rm_runlock 1218 0.3%
kernel`mac_ifnet_check_transmit 1287 0.3%
kernel`rtalloc1_fib 1305 0.3%
kernel`pf_test6 1344 0.3%
kernel`sched_runnable 1406 0.3%
kernel`key_addref 1674 0.4%
kernel`_rw_runlock_cookie 1762 0.4%
kernel`_key_freesp 1819 0.4%
kernel`__rw_rlock 2030 0.5%
kernel`in6_setscope 2293 0.5%
kernel`_rm_rlock 2312 0.5%
kernel`rn_match 2556 0.6%
kernel`ip6_forward 3647 0.8%
kernel`ip6_input 4139 0.9%
kernel`bzero 4237 1.0%
kernel`bcmp 10860 2.5%
kernel`cpu_idle 376300 85.8%
-- and here --
On Mon, Jun 23, 2014 at 10:18 PM, Vlad Galu <galu@packetdam.com> wrote:
> Hi John, thanks for reaching back. Yes, that must have been it, although
> the machine was completely idle at the time, except for my SSH session it
> was not generating or receiving any other traffic.
>
> I have since updated to r267702 and the problem seems to have magically
> disappeared... I still have the old kernel but can't currently reboot the
> machine. When I do next, I will revert to it and try to provide more
> information.
>
>
>
> On Mon, Jun 23, 2014 at 9:14 PM, John Baldwin <jhb@freebsd.org> wrote:
>
>> On Wednesday, June 18, 2014 7:12:33 am Vlad Galu wrote:
>> > CPU information:
>> > -- cut here --
>> > FreeBSD/SMP: Multiprocessor System Detected: 8 CPUs
>> > FreeBSD/SMP: 1 package(s) x 4 core(s) x 2 SMT threads
>> > -- and here --
>> >
>> > top output:
>> > -- cut here --
>> > last pid: 51987; load averages: 2.00, 2.00, 2.00
>> >
>> >
>> >
>> > up 8+18:47:58 13:07:02
>> > 520 processes: 11 running, 489 sleeping, 20 waiting
>> > CPU 0: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
>> > CPU 1: 0.0% user, 0.0% nice, 0.0% system, 100% interrupt, 0.0% idle
>> > CPU 2: 0.0% user, 0.0% nice, 0.4% system, 0.0% interrupt, 99.6% idle
>> > CPU 3: 0.4% user, 0.0% nice, 0.0% system, 0.0% interrupt, 99.6% idle
>> > CPU 4: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle
>> > CPU 5: 0.0% user, 0.0% nice, 0.8% system, 0.0% interrupt, 99.2% idle
>> > CPU 6: 0.0% user, 0.0% nice, 0.4% system, 0.0% interrupt, 99.6% idle
>> > CPU 7: 0.0% user, 0.0% nice, 0.0% system, 0.4% interrupt, 99.6% idle
>> > Mem: 87M Active, 2102M Inact, 11G Wired, 3656K Cache, 17G Free
>> > ARC: 8192M Total, 4089M MFU, 3372M MRU, 1936K Anon, 66M Header, 663M
>> Other
>> > Swap: 32G Total, 32G Free
>> >
>> > PID USERNAME PRI NICE SIZE RES STATE C TIME WCPU
>> COMMAND
>> > 11 root 155 ki31 0K 128K CPU0 0 210.1H 100.00%
>> > idle{idle: cpu0}
>> > 11 root 155 ki31 0K 128K CPU5 5 209.9H 100.00%
>> > idle{idle: cpu5}
>> > 11 root 155 ki31 0K 128K CPU7 7 209.9H 100.00%
>> > idle{idle: cpu7}
>> > 11 root 155 ki31 0K 128K CPU4 4 209.1H 100.00%
>> > idle{idle: cpu4}
>> > 11 root 155 ki31 0K 128K RUN 3 189.9H 100.00%
>> > idle{idle: cpu3}
>> > 11 root 155 ki31 0K 128K CPU2 2 173.3H 100.00%
>> > idle{idle: cpu2}
>> > 11 root 155 ki31 0K 128K CPU6 6 163.4H 100.00%
>> > idle{idle: cpu6}
>> > 12 root -72 - 0K 336K CPU1 1 141.0H 100.00%
>> > intr{swi1: netisr 0}
>>
>> This ithread? (ithreads count as intr time)
>>
>> --
>> John Baldwin
>>
>
>
>
> --
> Regards,
> Vlad
>
--
Regards,
Vlad
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CABN%2B6JmjUVg1z-nC1LmZNYeWffWyKzhrP7=6B_q5KSHav2ocfA>