>Number:         36169
>Category:       kern
>Synopsis:       Subject: 1sec+ delays using msync(2) with flags MS_ASYNC | MS_INVALIDATE
>Confidential:   no
>Severity:       non-critical
>Priority:       medium
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Wed Apr 18 20:05:00 +0000 2007
>Originator:     Brian de Alwis
>Release:        NetBSD 4.99.17 (updated 2007/04/17)
>Organization:
  Brian de Alwis | Software Practices Lab | UBC | http://www.cs.ubc.ca/~bsd/
      "Amusement to an observing mind is study." - Benjamin Disraeli
>Environment:

    System: NetBSD monolith 4.99.17 NetBSD 4.99.17 (LAPTOP.MP) #1: Tue Apr 17 23:13:03 CST 2007 bsd@monolith:/usr/obj/sys/arch/i386/compile/LAPTOP.MP i386
    Architecture: i386
    Machine: i386
    LAPTOP.MP includes GENERIC.MP

This is an Intel 2GHz Core Duo with 1GB of memory.

    cpu0 at mainbus0 apid 0: (boot processor)
    cpu0: Intel Pentium M (Yonah) (686-class), 1995.20 MHz, id 0x6e8
    cpu0: features
    bfe9fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR>
    cpu0: features bfe9fbff<PGE,MCA,CMOV,PAT,CFLUSH,DS,ACPI,MMX>
    cpu0: features bfe9fbff<FXSR,SSE,SSE2,SS,HTT,TM,SBF>
    cpu0: features2 c1a9<SSE3,MONITOR,VMX,EST,TM2,xTPR>
    cpu0: "Genuine Intel(R) CPU           T2500  @ 2.00GHz"
    cpu0: I-cache 32 KB 64B/line 8-way, D-cache 32 KB 64B/line 8-way
    cpu0: L2 cache 2 MB 64B/line 8-way
    cpu0: using thermal monitor 1
    cpu0: Enhanced SpeedStep (1404 mV) 2000 MHz
    cpu0: unknown Enhanced SpeedStep CPU.
    cpu0: using only highest and lowest power states.
    cpu0: Enhanced SpeedStep frequencies available (MHz): 2000 1000
    cpu0: calibrating local timer
    cpu0: apic clock running at 166 MHz
    cpu0: 64 page colors
    cpu1 at mainbus0 apid 1: (application processor)
    cpu1: Intel Pentium M (Yonah) (686-class), 1995.00 MHz, id 0x6e8
    cpu1: features bfe9fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR>
    cpu1: features bfe9fbff<PGE,MCA,CMOV,PAT,CFLUSH,DS,ACPI,MMX>
    cpu1: features bfe9fbff<FXSR,SSE,SSE2,SS,HTT,TM,SBF>
    cpu1: features2 c1a9<SSE3,MONITOR,VMX,EST,TM2,xTPR>
    cpu1: "Genuine Intel(R) CPU           T2500  @ 2.00GHz"
    cpu1: I-cache 32 KB 64B/line 8-way, D-cache 32 KB 64B/line 8-way
    cpu1: L2 cache 2 MB 64B/line 8-way
    cpu1: using thermal monitor 1

>Description:
    Summary: a call to msync(2) with flags MS_ASYNC | MS_INVALIDATE
    appears to be done as a synchronous call, and can take >1sec.
    Should it? How can I avoid it?

    I'm packaging up crm114 for pkgsrc: crm114 is a powerful text
    classifier that does particularly well for spam filtering,
    amongst other uses.  (It's in wip/crm114; it's marked as broken
    for now as some of its more esoteric classifiers currently fail
    the tests, though it does compile and work with the usual
    classifiers.)

    I'm trying to figure out why causes a long sustained disk write
    of a second or more on each spam classification.  ktrace -R
    reports that almost a second is spent in a call to __msync13():

	0.9941388845 CALL  __msync13(0xbb7df000,0x2dc714,3)

	corresponding to a call in the source:

	    msync (map->addr, map->actual_len, MS_ASYNC |
	    MS_INVALIDATE);

	crm114 does most of its file manipulation by mmaping
	the files to memory and uses the contents as a hash
	table.  In my case there are two spam classification
	mmaps (sparse files) which are 3,000,084 bytes each.
	So although MS_ASYNC is specified, it appears the sync
	is actually treated as synchronous.  Should it be?
	How it be avoided? (I'm not sure why the author uses
	MS_INVALIDATE.)

	Compounding this problem is that the spam processing
	does this for each message processed.

>How-To-Repeat:
	1. Install wip/crm114 (remove BROKEN line)
	2. Create the CRM classification setup:
	    $ mkdir foo; cd foo; \
	      cssutil -b -r spam.css; \
	      cssutil -b -r nonspam.css; \
	      cp /usr/pkg/share/examples/crm114/mailfilter.cf .; \
	      :>rewrites.mfp; \
	      :>priolist.mfp; \
	      :>whitelist.mfp; \
	      :>blacklist.mfp
	3. The following ensures that the mail cache is set up
	    $ crm /usr/pkg/share/crm114/mailreaver.crm \
		-u /usr/pkg/share/crm114 \
		--fileprefix=$PWD/ \
		< /dev/null
	3. save a mail message to /tmp/message
	4. Now try classifying the message:
	    $ crm /usr/pkg/share/crm114/mailreaver.crm \
		-u /usr/pkg/share/crm114 \
		--fileprefix=$PWD/ \
		</tmp/message

    You should get a *very* long pause after step four.  Running
    step four a second time takes equally long -- nothing seems to
    be cached.

    If you run it under `ktrace -di crm ...', and then examine the
    output sorting by relative-time-taken, you'll see something like:

	$ kdump -R -m0 \
	| awk '{ printf "%1.9f %5d %2d %-8s ", $4, $1, $2, $3; \
	    for(i=5; i<=NF; i++) { printf "%s ", $i; }; printf "\n"; }' \
	| sort -nr \
	| sed -n '1,10p'

	13.002756635 23182  1 crm      CALL __msync13(0xbaebb000,0xc0000c,3) 
	0.071855785 23182  1 crm      CALL break(0xc378000) 
	0.021222601 23182  1 crm      CALL open(0xbfbf8d32,2,0x1b6) 
	0.020033204 23182  1 crm      RET nanosleep 0 
	0.020025242 23182  1 crm      RET nanosleep 0 
	0.019999611 23182  1 crm      RET nanosleep 0 
	0.019986689 23182  1 crm      RET nanosleep 0 
	0.019961338 23182  1 crm      RET nanosleep 0 
	0.019952956 23182  1 crm      RET nanosleep 0 
	0.016137317 23182  1 crm      RET nanosleep 0 

>Fix:

-- 
  Brian de Alwis | Software Practices Lab | UBC | http://www.cs.ubc.ca/~bsd/
      "Amusement to an observing mind is study." - Benjamin Disraeli